diff --git a/logd/Android.bp b/logd/Android.bp index 3df59f5f4..80e3cb2c9 100644 --- a/logd/Android.bp +++ b/logd/Android.bp @@ -33,11 +33,12 @@ cc_library_static { srcs: [ "LogCommand.cpp", + "ChattyLogBuffer.cpp", "CommandListener.cpp", "LogListener.cpp", "LogReader.cpp", + "LogReaderList.cpp", "LogReaderThread.cpp", - "LogBuffer.cpp", "LogBufferElement.cpp", "LogStatistics.cpp", "LogWhiteBlackList.cpp", diff --git a/logd/LogBuffer.cpp b/logd/ChattyLogBuffer.cpp similarity index 81% rename from logd/LogBuffer.cpp rename to logd/ChattyLogBuffer.cpp index 4fce7512b..fa5bceef0 100644 --- a/logd/LogBuffer.cpp +++ b/logd/ChattyLogBuffer.cpp @@ -13,9 +13,11 @@ * See the License for the specific language governing permissions and * limitations under the License. */ -// for manual checking of stale entries during LogBuffer::erase() +// for manual checking of stale entries during ChattyLogBuffer::erase() //#define DEBUG_CHECK_FOR_STALE_ENTRIES +#include "ChattyLogBuffer.h" + #include #include #include @@ -32,7 +34,6 @@ #include #include -#include "LogBuffer.h" #include "LogKlog.h" #include "LogReader.h" #include "LogUtils.h" @@ -44,27 +45,22 @@ // Default #define log_buffer_size(id) mMaxSize[id] -void LogBuffer::init() { +void ChattyLogBuffer::Init() { log_id_for_each(i) { - if (setSize(i, __android_logger_get_buffer_size(i))) { - setSize(i, LOG_BUFFER_MIN_SIZE); + 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. - LogReaderThread::wrlock(); - - LastLogTimes::iterator times = mTimes.begin(); - while (times != mTimes.end()) { - LogReaderThread* entry = times->get(); - entry->triggerReader_Locked(); - times++; + 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(); } - - LogReaderThread::unlock(); } -LogBuffer::LogBuffer(LastLogTimes* times, LogTags* tags, PruneList* prune, LogStatistics* stats) - : mTimes(*times), tags_(tags), prune_(prune), stats_(stats) { +ChattyLogBuffer::ChattyLogBuffer(LogReaderList* reader_list, LogTags* tags, PruneList* prune, + LogStatistics* stats) + : reader_list_(reader_list), tags_(tags), prune_(prune), stats_(stats) { pthread_rwlock_init(&mLogElementsLock, nullptr); log_id_for_each(i) { @@ -72,17 +68,17 @@ LogBuffer::LogBuffer(LastLogTimes* times, LogTags* tags, PruneList* prune, LogSt droppedElements[i] = nullptr; } - init(); + Init(); } -LogBuffer::~LogBuffer() { +ChattyLogBuffer::~ChattyLogBuffer() { log_id_for_each(i) { delete lastLoggedElements[i]; delete droppedElements[i]; } } -LogBufferElementCollection::iterator LogBuffer::GetOldest(log_id_t log_id) { +LogBufferElementCollection::iterator ChattyLogBuffer::GetOldest(log_id_t log_id) { auto it = mLogElements.begin(); if (oldest_[log_id]) { it = *oldest_[log_id]; @@ -98,8 +94,7 @@ LogBufferElementCollection::iterator LogBuffer::GetOldest(log_id_t log_id) { 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(); @@ -113,8 +108,7 @@ static enum match_type identical(LogBufferElement* elem, if (elem->getTid() != last->getTid()) return DIFFERENT; // last is more than a minute old, stop squashing identical messages - if (elem->getRealTime().nsec() > - (last->getRealTime().nsec() + 60 * NS_PER_SEC)) + if (elem->getRealTime().nsec() > (last->getRealTime().nsec() + 60 * NS_PER_SEC)) return DIFFERENT; // Identical message @@ -123,21 +117,17 @@ static enum match_type identical(LogBufferElement* elem, if (lenl == lenr) { if (!fastcmp(msgl, msgr, lenl)) return SAME; // liblog tagged messages (content gets summed) - if ((elem->getLogId() == LOG_ID_EVENTS) && - (lenl == sizeof(android_log_event_int_t)) && - !fastcmp(msgl, msgr, sizeof(android_log_event_int_t) - - sizeof(int32_t)) && - (elem->getTag() == LIBLOG_LOG_TAG)) { + if (elem->getLogId() == LOG_ID_EVENTS && lenl == sizeof(android_log_event_int_t) && + !fastcmp(msgl, msgr, sizeof(android_log_event_int_t) - sizeof(int32_t)) && + elem->getTag() == LIBLOG_LOG_TAG) { return SAME_LIBLOG; } } // audit message (except sequence number) identical? - if (last->isBinary() && - (lenl > static_cast(sizeof(android_log_event_string_t))) && - (lenr > static_cast(sizeof(android_log_event_string_t)))) { - if (fastcmp(msgl, msgr, sizeof(android_log_event_string_t) - - sizeof(int32_t))) { + if (last->isBinary() && lenl > static_cast(sizeof(android_log_event_string_t)) && + lenr > static_cast(sizeof(android_log_event_string_t))) { + if (fastcmp(msgl, msgr, sizeof(android_log_event_string_t) - sizeof(int32_t))) { return DIFFERENT; } msgl += sizeof(android_log_event_string_t); @@ -153,15 +143,14 @@ static enum match_type identical(LogBufferElement* elem, if (!avcr) return DIFFERENT; lenr -= avcr - msgr; if (lenl != lenr) return DIFFERENT; - if (fastcmp(avcl + strlen(avc), avcr + strlen(avc), - lenl - strlen(avc))) { + if (fastcmp(avcl + strlen(avc), avcr + strlen(avc), lenl - strlen(avc))) { return DIFFERENT; } return SAME; } -int LogBuffer::log(log_id_t log_id, log_time realtime, uid_t uid, pid_t pid, - pid_t tid, const char* msg, uint16_t len) { +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; } @@ -283,8 +272,7 @@ int LogBuffer::log(log_id_t log_id, log_time realtime, uid_t uid, pid_t pid, if (dropped) { // Sum up liblog tag messages? if ((count == 0) /* at Pass 1 */ && (match == SAME_LIBLOG)) { - android_log_event_int_t* event = - reinterpret_cast( + android_log_event_int_t* event = reinterpret_cast( const_cast(currentLast->getMsg())); // // To unit test, differentiate with something like: @@ -295,7 +283,7 @@ int LogBuffer::log(log_id_t log_id, log_time realtime, uid_t uid, pid_t pid, uint32_t swab = event->payload.data; unsigned long long total = htole32(swab); event = reinterpret_cast( - const_cast(elem->getMsg())); + const_cast(elem->getMsg())); swab = event->payload.data; lastLoggedElements[LOG_ID_EVENTS] = elem; @@ -350,23 +338,24 @@ int LogBuffer::log(log_id_t log_id, log_time realtime, uid_t uid, pid_t pid, return len; } -// assumes LogBuffer::wrlock() held, owns elem, look after garbage collection -void LogBuffer::log(LogBufferElement* elem) { +// assumes ChattyLogBuffer::wrlock() held, owns elem, look after garbage collection +void ChattyLogBuffer::log(LogBufferElement* elem) { mLogElements.push_back(elem); stats_->Add(elem); maybePrune(elem->getLogId()); + reader_list_->NotifyNewLog(1 << elem->getLogId()); } -// LogBuffer::wrlock() must be held when this function is called. -void LogBuffer::maybePrune(log_id_t id) { +// ChattyLogBuffer::wrlock() must be held when this function is called. +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 LogBuffer::erase( - LogBufferElementCollection::iterator it, bool coalesce) { +LogBufferElementCollection::iterator ChattyLogBuffer::erase(LogBufferElementCollection::iterator it, + bool coalesce) { LogBufferElement* element = *it; log_id_t id = element->getLogId(); @@ -374,9 +363,8 @@ LogBufferElementCollection::iterator LogBuffer::erase( // after the element is erased from the main logging list. { // start of scope for found iterator - int key = ((id == LOG_ID_EVENTS) || (id == LOG_ID_SECURITY)) - ? element->getTag() - : element->getUid(); + int key = (id == LOG_ID_EVENTS || id == LOG_ID_SECURITY) ? element->getTag() + : element->getUid(); LogBufferIteratorMap::iterator found = mLastWorst[id].find(key); if ((found != mLastWorst[id].end()) && (it == found->second)) { mLastWorst[id].erase(found); @@ -387,10 +375,8 @@ LogBufferElementCollection::iterator LogBuffer::erase( // element->getUid() may not be AID_SYSTEM for next-best-watermark. // will not assume id != LOG_ID_EVENTS or LOG_ID_SECURITY for KISS and // long term code stability, find() check should be fast for those ids. - LogBufferPidIteratorMap::iterator found = - mLastWorstPidOfSystem[id].find(element->getPid()); - if ((found != mLastWorstPidOfSystem[id].end()) && - (it == found->second)) { + LogBufferPidIteratorMap::iterator found = mLastWorstPidOfSystem[id].find(element->getPid()); + if (found != mLastWorstPidOfSystem[id].end() && it == found->second) { mLastWorstPidOfSystem[id].erase(found); } } @@ -400,9 +386,8 @@ LogBufferElementCollection::iterator LogBuffer::erase( 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 = ((id == LOG_ID_EVENTS) || (id == LOG_ID_SECURITY)) - ? element->getTag() - : element->getUid(); + int key = + (id == LOG_ID_EVENTS || id == LOG_ID_SECURITY) ? element->getTag() : element->getUid(); #endif it = mLogElements.erase(it); if (doSetLast) { @@ -421,14 +406,12 @@ LogBufferElementCollection::iterator LogBuffer::erase( log_id_for_each(i) { for (auto b : mLastWorst[i]) { if (bad == b.second) { - android::prdebug("stale mLastWorst[%d] key=%d mykey=%d\n", i, - b.first, key); + android::prdebug("stale mLastWorst[%d] key=%d mykey=%d\n", i, b.first, key); } } for (auto b : mLastWorstPidOfSystem[i]) { if (bad == b.second) { - android::prdebug("stale mLastWorstPidOfSystem[%d] pid=%d\n", i, - b.first); + android::prdebug("stale mLastWorstPidOfSystem[%d] pid=%d\n", i, b.first); } } } @@ -456,26 +439,20 @@ class LogBufferElementKey { uint64_t value; } __packed; - public: - LogBufferElementKey(uid_t uid, pid_t pid, pid_t tid) - : uid(uid), pid(pid), tid(tid) { - } - explicit LogBufferElementKey(uint64_t key) : value(key) { - } + public: + LogBufferElementKey(uid_t uid, pid_t pid, pid_t tid) : uid(uid), pid(pid), tid(tid) {} + explicit LogBufferElementKey(uint64_t key) : value(key) {} - uint64_t getKey() { - return value; - } + uint64_t getKey() { return value; } }; class LogBufferElementLast { typedef std::unordered_map LogBufferElementMap; LogBufferElementMap map; - public: + public: bool coalesce(LogBufferElement* element, uint16_t dropped) { - LogBufferElementKey key(element->getUid(), element->getPid(), - element->getTid()); + LogBufferElementKey key(element->getUid(), element->getPid(), element->getTid()); LogBufferElementMap::iterator it = map.find(key.getKey()); if (it != map.end()) { LogBufferElement* found = it->second; @@ -491,14 +468,11 @@ class LogBufferElementLast { } void add(LogBufferElement* element) { - LogBufferElementKey key(element->getUid(), element->getPid(), - element->getTid()); + LogBufferElementKey key(element->getUid(), element->getPid(), element->getTid()); map[key.getKey()] = element; } - inline void clear() { - map.clear(); - } + void clear() { map.clear(); } void clear(LogBufferElement* element) { uint64_t current = element->getRealTime().nsec() - (EXPIRE_RATELIMIT * NS_PER_SEC); @@ -516,21 +490,20 @@ class LogBufferElementLast { // If the selected reader is blocking our pruning progress, decide on // what kind of mitigation is necessary to unblock the situation. -void LogBuffer::kickMe(LogReaderThread* me, log_id_t id, unsigned long pruneRows) { +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, pid %d, from LogBuffer::kickMe()\n", + android::prdebug("Kicking blocked reader, pid %d, from ChattyLogBuffer::kickMe()\n", me->client()->getPid()); me->release_Locked(); - } else if (me->timeout().tv_sec || me->timeout().tv_nsec) { - // Allow a blocked WRAP timeout reader to - // trigger and start reporting the log data. + } 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, pid %d, from LogBuffer::kickMe()\n", + "Skipping %lu entries from slow reader, pid %d, from ChattyLogBuffer::kickMe()\n", pruneRows, me->client()->getPid()); me->triggerSkip_Locked(id, pruneRows); } @@ -581,25 +554,25 @@ void LogBuffer::kickMe(LogReaderThread* me, log_id_t id, unsigned long pruneRows // The third thread is optional, and only gets hit if there was a whitelist // and more needs to be pruned against the backstop of the region lock. // -// LogBuffer::wrlock() must be held when this function is called. +// ChattyLogBuffer::wrlock() must be held when this function is called. // -bool LogBuffer::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; - LogReaderThread::rdlock(); + auto reader_threads_lock = std::lock_guard{reader_list_->reader_threads_lock()}; // Region locked? - LastLogTimes::iterator times = mTimes.begin(); - while (times != mTimes.end()) { - LogReaderThread* entry = times->get(); - if (entry->IsWatching(id) && (!oldest || oldest->start() > entry->start() || - (oldest->start() == entry->start() && - (entry->timeout().tv_sec || entry->timeout().tv_nsec)))) { - oldest = entry; + 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(); } - times++; } LogBufferElementCollection::iterator it; @@ -611,8 +584,7 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { while (it != mLogElements.end()) { LogBufferElement* element = *it; - if ((element->getLogId() != id) || - (element->getUid() != caller_uid)) { + if (element->getLogId() != id || element->getUid() != caller_uid) { ++it; continue; } @@ -628,7 +600,6 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { break; } } - LogReaderThread::unlock(); return busy; } @@ -672,10 +643,8 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { bool gc = pruneRows <= 1; if (!gc && (worst != -1)) { { // begin scope for worst found iterator - LogBufferIteratorMap::iterator found = - mLastWorst[id].find(worst); - if ((found != mLastWorst[id].end()) && - (found->second != mLogElements.end())) { + LogBufferIteratorMap::iterator found = mLastWorst[id].find(worst); + if (found != mLastWorst[id].end() && found->second != mLogElements.end()) { leading = false; it = found->second; } @@ -683,10 +652,9 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { if (worstPid) { // begin scope for pid worst found iterator // FYI: worstPid only set if !LOG_ID_EVENTS and // !LOG_ID_SECURITY, not going to make that assumption ... - LogBufferPidIteratorMap::iterator found = - mLastWorstPidOfSystem[id].find(worstPid); - if ((found != mLastWorstPidOfSystem[id].end()) && - (found->second != mLogElements.end())) { + LogBufferPidIteratorMap::iterator found = mLastWorstPidOfSystem[id].find(worstPid); + if (found != mLastWorstPidOfSystem[id].end() && + found->second != mLogElements.end()) { leading = false; it = found->second; } @@ -695,7 +663,7 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { if (leading) { it = GetOldest(id); } - static const timespec too_old = { EXPIRE_HOUR_THRESHOLD * 60 * 60, 0 }; + static const timespec too_old = {EXPIRE_HOUR_THRESHOLD * 60 * 60, 0}; LogBufferElementCollection::iterator lastt; lastt = mLogElements.end(); --lastt; @@ -728,9 +696,8 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { continue; } - int key = ((id == LOG_ID_EVENTS) || (id == LOG_ID_SECURITY)) - ? element->getTag() - : element->getUid(); + int key = (id == LOG_ID_EVENTS || id == LOG_ID_SECURITY) ? element->getTag() + : element->getUid(); if (hasBlacklist && prune_->naughty(element)) { last.clear(element); @@ -761,10 +728,9 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { if (dropped) { last.add(element); - if (worstPid && - ((!gc && (element->getPid() == worstPid)) || - (mLastWorstPidOfSystem[id].find(element->getPid()) == - mLastWorstPidOfSystem[id].end()))) { + if (worstPid && ((!gc && element->getPid() == worstPid) || + mLastWorstPidOfSystem[id].find(element->getPid()) == + mLastWorstPidOfSystem[id].end())) { // element->getUid() may not be AID_SYSTEM, next best // watermark if current one empty. id is not LOG_ID_EVENTS // or LOG_ID_SECURITY because of worstPid check. @@ -778,8 +744,7 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { continue; } - if ((key != worst) || - (worstPid && (element->getPid() != worstPid))) { + if (key != worst || (worstPid && element->getPid() != worstPid)) { leading = false; last.clear(element); ++it; @@ -807,16 +772,14 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { it = erase(it, true); } else { last.add(element); - if (worstPid && - (!gc || (mLastWorstPidOfSystem[id].find(worstPid) == - mLastWorstPidOfSystem[id].end()))) { + if (worstPid && (!gc || mLastWorstPidOfSystem[id].find(worstPid) == + mLastWorstPidOfSystem[id].end())) { // element->getUid() may not be AID_SYSTEM, next best // watermark if current one empty. id is not // LOG_ID_EVENTS or LOG_ID_SECURITY because of worstPid. mLastWorstPidOfSystem[id][worstPid] = it; } - if ((!gc && !worstPid) || - (mLastWorst[id].find(worst) == mLastWorst[id].end())) { + if ((!gc && !worstPid) || mLastWorst[id].find(worst) == mLastWorst[id].end()) { mLastWorst[id][worst] = it; } ++it; @@ -884,13 +847,11 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) { } } - LogReaderThread::unlock(); - return (pruneRows > 0) && busy; } // clear all rows of type "id" from the buffer. -bool LogBuffer::clear(log_id_t id, uid_t uid) { +bool 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;;) { @@ -907,20 +868,15 @@ bool LogBuffer::clear(log_id_t id, uid_t uid) { // readers and let the clear run (below) deal with determining // if we are still blocked and return an error code to caller. if (busy) { - LogReaderThread::wrlock(); - LastLogTimes::iterator times = mTimes.begin(); - while (times != mTimes.end()) { - LogReaderThread* entry = times->get(); - // Killer punch - if (entry->IsWatching(id)) { + 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, pid %d, from LogBuffer::clear()\n", - entry->client()->getPid()); - entry->release_Locked(); + "Kicking blocked reader, pid %d, from ChattyLogBuffer::clear()\n", + reader_thread->client()->getPid()); + reader_thread->release_Locked(); } - times++; } - LogReaderThread::unlock(); } } wrlock(); @@ -935,7 +891,7 @@ bool LogBuffer::clear(log_id_t id, uid_t uid) { } // set the total space allocated to "id" -int LogBuffer::setSize(log_id_t id, unsigned long size) { +int ChattyLogBuffer::SetSize(log_id_t id, unsigned long size) { // Reasonable limits ... if (!__android_logger_valid_buffer_size(size)) { return -1; @@ -947,16 +903,16 @@ int LogBuffer::setSize(log_id_t id, unsigned long size) { } // get the total space allocated to "id" -unsigned long LogBuffer::getSize(log_id_t id) { +unsigned long ChattyLogBuffer::GetSize(log_id_t id) { rdlock(); size_t retval = log_buffer_size(id); unlock(); return retval; } -uint64_t LogBuffer::flushTo(SocketClient* reader, uint64_t start, pid_t* lastTid, bool privileged, - bool security, - const std::function& filter) { +uint64_t ChattyLogBuffer::FlushTo( + SocketClient* reader, uint64_t start, pid_t* lastTid, bool privileged, bool security, + const std::function& filter) { LogBufferElementCollection::iterator it; uid_t uid = reader->getUid(); @@ -994,11 +950,11 @@ uint64_t LogBuffer::flushTo(SocketClient* reader, uint64_t start, pid_t* lastTid // NB: calling out to another object with wrlock() held (safe) if (filter) { - int ret = filter(element); - if (ret == false) { + FlushToResult ret = filter(element); + if (ret == FlushToResult::kSkip) { continue; } - if (ret != true) { + if (ret == FlushToResult::kStop) { break; } } @@ -1012,7 +968,7 @@ uint64_t LogBuffer::flushTo(SocketClient* reader, uint64_t start, pid_t* lastTid // 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(); + (element->getDropped() && !sameTid) ? 0 : element->getTid(); } unlock(); diff --git a/logd/ChattyLogBuffer.h b/logd/ChattyLogBuffer.h new file mode 100644 index 000000000..d9cd24f11 --- /dev/null +++ b/logd/ChattyLogBuffer.h @@ -0,0 +1,97 @@ +/* + * Copyright (C) 2012-2014 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +#pragma once + +#include + +#include +#include +#include + +#include +#include +#include + +#include "LogBuffer.h" +#include "LogBufferElement.h" +#include "LogStatistics.h" +#include "LogTags.h" +#include "LogWhiteBlackList.h" + +typedef std::list LogBufferElementCollection; + +class LogReaderList; +class LogReaderThread; + +class ChattyLogBuffer : public LogBuffer { + LogBufferElementCollection mLogElements; + pthread_rwlock_t mLogElementsLock; + + // watermark of any worst/chatty uid processing + typedef std::unordered_map LogBufferIteratorMap; + LogBufferIteratorMap mLastWorst[LOG_ID_MAX]; + // watermark of any worst/chatty pid of system processing + typedef std::unordered_map LogBufferPidIteratorMap; + LogBufferPidIteratorMap mLastWorstPidOfSystem[LOG_ID_MAX]; + + unsigned long mMaxSize[LOG_ID_MAX]; + + LogBufferElement* lastLoggedElements[LOG_ID_MAX]; + LogBufferElement* droppedElements[LOG_ID_MAX]; + void log(LogBufferElement* elem); + + 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( + SocketClient* writer, uint64_t start, pid_t* lastTid, bool privileged, bool security, + 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; + + private: + void wrlock() { pthread_rwlock_wrlock(&mLogElementsLock); } + void rdlock() { pthread_rwlock_rdlock(&mLogElementsLock); } + void unlock() { pthread_rwlock_unlock(&mLogElementsLock); } + + void maybePrune(log_id_t id); + void kickMe(LogReaderThread* me, log_id_t id, unsigned long pruneRows); + + bool prune(log_id_t id, unsigned long pruneRows, uid_t uid = AID_ROOT); + LogBufferElementCollection::iterator erase(LogBufferElementCollection::iterator it, + bool coalesce = false); + + // 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); + + 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]; +}; diff --git a/logd/CommandListener.cpp b/logd/CommandListener.cpp index 87402acc3..0ff19f859 100644 --- a/logd/CommandListener.cpp +++ b/logd/CommandListener.cpp @@ -81,7 +81,7 @@ int CommandListener::ClearCmd::runCommand(SocketClient* cli, int argc, return 0; } - cli->sendMsg(buf()->clear((log_id_t)id, uid) ? "busy" : "success"); + cli->sendMsg(buf()->Clear((log_id_t)id, uid) ? "busy" : "success"); return 0; } @@ -99,7 +99,7 @@ int CommandListener::GetBufSizeCmd::runCommand(SocketClient* cli, int argc, return 0; } - unsigned long size = buf()->getSize((log_id_t)id); + unsigned long size = buf()->GetSize((log_id_t)id); char buf[512]; snprintf(buf, sizeof(buf), "%lu", size); cli->sendMsg(buf); @@ -126,7 +126,7 @@ int CommandListener::SetBufSizeCmd::runCommand(SocketClient* cli, int argc, } unsigned long size = atol(argv[2]); - if (buf()->setSize((log_id_t)id, size)) { + if (buf()->SetSize((log_id_t)id, size)) { cli->sendMsg("Range Error"); return 0; } @@ -299,7 +299,7 @@ int CommandListener::ReinitCmd::runCommand(SocketClient* cli, int /*argc*/, setname(); android::prdebug("logd reinit"); - buf()->init(); + buf()->Init(); prune()->init(nullptr); // This only works on userdebug and eng devices to re-read the diff --git a/logd/LogAudit.cpp b/logd/LogAudit.cpp index 6c42a289f..0ce9796b0 100644 --- a/logd/LogAudit.cpp +++ b/logd/LogAudit.cpp @@ -37,7 +37,6 @@ #include #include "LogKlog.h" -#include "LogReader.h" #include "LogUtils.h" #include "libaudit.h" @@ -45,10 +44,9 @@ '<', '0' + LOG_MAKEPRI(LOG_AUTH, LOG_PRI(PRI)) / 10, \ '0' + LOG_MAKEPRI(LOG_AUTH, LOG_PRI(PRI)) % 10, '>' -LogAudit::LogAudit(LogBuffer* buf, LogReader* reader, int fdDmesg, LogStatistics* stats) +LogAudit::LogAudit(LogBuffer* buf, int fdDmesg, LogStatistics* stats) : SocketListener(getLogSocket(), false), logbuf(buf), - reader(reader), fdDmesg(fdDmesg), main(__android_logger_property_get_bool("ro.logd.auditd.main", BOOL_DEFAULT_TRUE)), events(__android_logger_property_get_bool("ro.logd.auditd.events", BOOL_DEFAULT_TRUE)), @@ -276,9 +274,8 @@ int LogAudit::logPrint(const char* fmt, ...) { memcpy(event->data + str_len - denial_metadata.length(), denial_metadata.c_str(), denial_metadata.length()); - rc = logbuf->log( - LOG_ID_EVENTS, now, uid, pid, tid, reinterpret_cast(event), - (message_len <= UINT16_MAX) ? (uint16_t)message_len : UINT16_MAX); + rc = logbuf->Log(LOG_ID_EVENTS, now, uid, pid, tid, reinterpret_cast(event), + (message_len <= UINT16_MAX) ? (uint16_t)message_len : UINT16_MAX); if (rc >= 0) { notify |= 1 << LOG_ID_EVENTS; } @@ -330,9 +327,8 @@ int LogAudit::logPrint(const char* fmt, ...) { strncpy(newstr + 1 + str_len + prefix_len + suffix_len, denial_metadata.c_str(), denial_metadata.length()); - rc = logbuf->log( - LOG_ID_MAIN, now, uid, pid, tid, newstr, - (message_len <= UINT16_MAX) ? (uint16_t)message_len : UINT16_MAX); + rc = logbuf->Log(LOG_ID_MAIN, now, uid, pid, tid, newstr, + (message_len <= UINT16_MAX) ? (uint16_t)message_len : UINT16_MAX); if (rc >= 0) { notify |= 1 << LOG_ID_MAIN; @@ -344,7 +340,6 @@ int LogAudit::logPrint(const char* fmt, ...) { free(str); if (notify) { - reader->notifyNewLog(notify); if (rc < 0) { rc = message_len; } diff --git a/logd/LogAudit.h b/logd/LogAudit.h index ee6e57939..181920e38 100644 --- a/logd/LogAudit.h +++ b/logd/LogAudit.h @@ -23,18 +23,15 @@ #include "LogBuffer.h" #include "LogStatistics.h" -class LogReader; - class LogAudit : public SocketListener { LogBuffer* logbuf; - LogReader* reader; int fdDmesg; // fdDmesg >= 0 is functionally bool dmesg bool main; bool events; bool initialized; public: - LogAudit(LogBuffer* buf, LogReader* reader, int fdDmesg, LogStatistics* stats); + LogAudit(LogBuffer* buf, int fdDmesg, LogStatistics* stats); int log(char* buf, size_t len); protected: diff --git a/logd/LogBuffer.h b/logd/LogBuffer.h index 3c1ea5a2b..887e5f0e4 100644 --- a/logd/LogBuffer.h +++ b/logd/LogBuffer.h @@ -1,5 +1,5 @@ /* - * Copyright (C) 2012-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. @@ -18,89 +18,37 @@ #include -#include -#include -#include +#include -#include -#include +#include #include #include "LogBufferElement.h" -#include "LogReaderThread.h" -#include "LogStatistics.h" -#include "LogTags.h" -#include "LogWhiteBlackList.h" -typedef std::list LogBufferElementCollection; +enum class FlushToResult { + kSkip, + kStop, + kWrite, +}; class LogBuffer { - LogBufferElementCollection mLogElements; - pthread_rwlock_t mLogElementsLock; + public: + virtual ~LogBuffer() {} - // watermark of any worst/chatty uid processing - typedef std::unordered_map - LogBufferIteratorMap; - LogBufferIteratorMap mLastWorst[LOG_ID_MAX]; - // watermark of any worst/chatty pid of system processing - typedef std::unordered_map - LogBufferPidIteratorMap; - LogBufferPidIteratorMap mLastWorstPidOfSystem[LOG_ID_MAX]; + virtual void Init() = 0; - unsigned long mMaxSize[LOG_ID_MAX]; - - LogBufferElement* lastLoggedElements[LOG_ID_MAX]; - LogBufferElement* droppedElements[LOG_ID_MAX]; - void log(LogBufferElement* elem); - - public: - LastLogTimes& mTimes; - - LogBuffer(LastLogTimes* times, LogTags* tags, PruneList* prune, LogStatistics* stats); - ~LogBuffer(); - void init(); - - 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); + virtual 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) = 0; // lastTid is an optional context to help detect if the last previous // valid message was from the same source so we can differentiate chatty // filter types (identical or expired) - uint64_t flushTo(SocketClient* writer, uint64_t start, - pid_t* lastTid, // &lastTid[LOG_ID_MAX] or nullptr - bool privileged, bool security, - const std::function& filter); + virtual uint64_t FlushTo( + SocketClient* writer, uint64_t start, + pid_t* last_tid, // nullable + bool privileged, bool security, + const std::function& filter) = 0; - bool clear(log_id_t id, uid_t uid = AID_ROOT); - unsigned long getSize(log_id_t id); - int setSize(log_id_t id, unsigned long size); - - private: - void wrlock() { - pthread_rwlock_wrlock(&mLogElementsLock); - } - void rdlock() { - pthread_rwlock_rdlock(&mLogElementsLock); - } - void unlock() { - pthread_rwlock_unlock(&mLogElementsLock); - } - - void maybePrune(log_id_t id); - void kickMe(LogReaderThread* me, log_id_t id, unsigned long pruneRows); - - bool prune(log_id_t id, unsigned long pruneRows, uid_t uid = AID_ROOT); - LogBufferElementCollection::iterator erase( - LogBufferElementCollection::iterator it, bool coalesce = false); - - // 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); - - 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]; -}; + 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; +}; \ No newline at end of file diff --git a/logd/LogBufferElement.cpp b/logd/LogBufferElement.cpp index cc68ba4de..32f641b4e 100644 --- a/logd/LogBufferElement.cpp +++ b/logd/LogBufferElement.cpp @@ -27,9 +27,9 @@ #include #include -#include "LogBuffer.h" #include "LogCommand.h" #include "LogReader.h" +#include "LogStatistics.h" #include "LogUtils.h" const uint64_t LogBufferElement::FLUSH_ERROR(0); diff --git a/logd/LogBufferElement.h b/logd/LogBufferElement.h index 8676cf173..3d0b65e59 100644 --- a/logd/LogBufferElement.h +++ b/logd/LogBufferElement.h @@ -24,7 +24,6 @@ #include #include -class LogBuffer; class LogStatistics; #define EXPIRE_HOUR_THRESHOLD 24 // Only expire chatty UID logs to preserve @@ -34,8 +33,6 @@ class LogStatistics; #define EXPIRE_RATELIMIT 10 // maximum rate in seconds to report expiration class __attribute__((packed)) LogBufferElement { - friend LogBuffer; - // sized to match reality of incoming log packets const uint32_t mUid; const uint32_t mPid; diff --git a/logd/LogKlog.cpp b/logd/LogKlog.cpp index bc94b45c8..1ea87a91f 100644 --- a/logd/LogKlog.cpp +++ b/logd/LogKlog.cpp @@ -31,7 +31,6 @@ #include #include "LogBuffer.h" -#include "LogReader.h" #define KMSG_PRIORITY(PRI) \ '<', '0' + (LOG_SYSLOG | (PRI)) / 10, '0' + (LOG_SYSLOG | (PRI)) % 10, '>' @@ -202,11 +201,9 @@ log_time LogKlog::correction = (log_time(CLOCK_REALTIME) < log_time(CLOCK_MONOTO ? log_time(log_time::EPOCH) : (log_time(CLOCK_REALTIME) - log_time(CLOCK_MONOTONIC)); -LogKlog::LogKlog(LogBuffer* buf, LogReader* reader, int fdWrite, int fdRead, bool auditd, - LogStatistics* stats) +LogKlog::LogKlog(LogBuffer* buf, int fdWrite, int fdRead, bool auditd, LogStatistics* stats) : SocketListener(fdRead, false), logbuf(buf), - reader(reader), signature(CLOCK_MONOTONIC), initialized(false), enableLogging(true), @@ -770,12 +767,7 @@ int LogKlog::log(const char* buf, ssize_t len) { } // Log message - int rc = logbuf->log(LOG_ID_KERNEL, now, uid, pid, tid, newstr, (uint16_t)n); - - // notify readers - if (rc > 0) { - reader->notifyNewLog(static_cast(1 << LOG_ID_KERNEL)); - } + int rc = logbuf->Log(LOG_ID_KERNEL, now, uid, pid, tid, newstr, (uint16_t)n); return rc; } diff --git a/logd/LogKlog.h b/logd/LogKlog.h index a7dbe642f..77b24bc31 100644 --- a/logd/LogKlog.h +++ b/logd/LogKlog.h @@ -22,11 +22,9 @@ #include "LogStatistics.h" class LogBuffer; -class LogReader; class LogKlog : public SocketListener { LogBuffer* logbuf; - LogReader* reader; const log_time signature; // Set once thread is started, separates KLOG_ACTION_READ_ALL // and KLOG_ACTION_READ phases. @@ -40,8 +38,7 @@ class LogKlog : public SocketListener { static log_time correction; public: - LogKlog(LogBuffer* buf, LogReader* reader, int fdWrite, int fdRead, bool auditd, - LogStatistics* stats); + LogKlog(LogBuffer* buf, int fdWrite, int fdRead, bool auditd, LogStatistics* stats); int log(const char* buf, ssize_t len); static void convertMonotonicToReal(log_time& real) { real += correction; } diff --git a/logd/LogListener.cpp b/logd/LogListener.cpp index 92b384d3c..d2e2efa9e 100644 --- a/logd/LogListener.cpp +++ b/logd/LogListener.cpp @@ -32,8 +32,7 @@ #include "LogListener.h" #include "LogUtils.h" -LogListener::LogListener(LogBuffer* buf, LogReader* reader) - : socket_(GetLogSocket()), logbuf_(buf), reader_(reader) {} +LogListener::LogListener(LogBuffer* buf) : socket_(GetLogSocket()), logbuf_(buf) {} bool LogListener::StartListener() { if (socket_ <= 0) { @@ -117,13 +116,8 @@ void LogListener::HandleData() { // NB: hdr.msg_flags & MSG_TRUNC is not tested, silently passing a // truncated message to the logs. - int res = logbuf_->log(logId, header->realtime, cred->uid, cred->pid, header->tid, msg, - ((size_t)n <= UINT16_MAX) ? (uint16_t)n : UINT16_MAX); - if (res > 0) { - reader_->notifyNewLog(static_cast(1 << logId)); - } - - return; + logbuf_->Log(logId, header->realtime, cred->uid, cred->pid, header->tid, msg, + ((size_t)n <= UINT16_MAX) ? (uint16_t)n : UINT16_MAX); } int LogListener::GetLogSocket() { diff --git a/logd/LogListener.h b/logd/LogListener.h index ce3e0f23a..d468df818 100644 --- a/logd/LogListener.h +++ b/logd/LogListener.h @@ -21,7 +21,7 @@ class LogListener { public: - LogListener(LogBuffer* buf, LogReader* reader); + LogListener(LogBuffer* buf); bool StartListener(); private: @@ -31,5 +31,4 @@ class LogListener { int socket_; LogBuffer* logbuf_; - LogReader* reader_; }; diff --git a/logd/LogReader.cpp b/logd/LogReader.cpp index a590cef85..6f913720a 100644 --- a/logd/LogReader.cpp +++ b/logd/LogReader.cpp @@ -21,7 +21,10 @@ #include #include +#include + #include +#include #include #include "LogBuffer.h" @@ -33,27 +36,8 @@ static bool CanReadSecurityLogs(SocketClient* client) { return client->getUid() == AID_SYSTEM || client->getGid() == AID_SYSTEM; } -LogReader::LogReader(LogBuffer* logbuf) - : SocketListener(getLogSocket(), true), mLogbuf(*logbuf) { -} - -// When we are notified a new log entry is available, inform -// listening sockets who are watching this entry's log id. -void LogReader::notifyNewLog(unsigned int log_mask) { - LastLogTimes& times = mLogbuf.mTimes; - - LogReaderThread::wrlock(); - for (const auto& entry : times) { - if (!entry->IsWatchingMultiple(log_mask)) { - continue; - } - if (entry->timeout().tv_sec || entry->timeout().tv_nsec) { - continue; - } - entry->triggerReader_Locked(); - } - LogReaderThread::unlock(); -} +LogReader::LogReader(LogBuffer* logbuf, LogReaderList* reader_list) + : SocketListener(getLogSocket(), true), log_buffer_(logbuf), reader_list_(reader_list) {} // Note returning false will release the SocketClient instance. bool LogReader::onDataAvailable(SocketClient* cli) { @@ -74,15 +58,15 @@ bool LogReader::onDataAvailable(SocketClient* cli) { // Clients are only allowed to send one command, disconnect them if they // send another. - LogReaderThread::wrlock(); - for (const auto& entry : mLogbuf.mTimes) { - if (entry->client() == cli) { - entry->release_Locked(); - LogReaderThread::unlock(); - return false; + { + auto lock = std::lock_guard{reader_list_->reader_threads_lock()}; + for (const auto& entry : reader_list_->reader_threads()) { + if (entry->client() == cli) { + entry->release_Locked(); + return false; + } } } - LogReaderThread::unlock(); unsigned long tail = 0; static const char _tail[] = " tail="; @@ -99,11 +83,12 @@ bool LogReader::onDataAvailable(SocketClient* cli) { start.strptime(cp + sizeof(_start) - 1, "%s.%q"); } - uint64_t timeout = 0; + std::chrono::steady_clock::time_point deadline = {}; static const char _timeout[] = " timeout="; cp = strstr(buffer, _timeout); if (cp) { - timeout = atol(cp + sizeof(_timeout) - 1) * NS_PER_SEC + log_time(CLOCK_MONOTONIC).nsec(); + long timeout_seconds = atol(cp + sizeof(_timeout) - 1); + deadline = std::chrono::steady_clock::now() + std::chrono::seconds(timeout_seconds); } unsigned int logMask = -1; @@ -137,8 +122,8 @@ bool LogReader::onDataAvailable(SocketClient* cli) { if (!fastcmp(buffer, "dumpAndClose", 12)) { // Allow writer to get some cycles, and wait for pending notifications sched_yield(); - LogReaderThread::wrlock(); - LogReaderThread::unlock(); + reader_list_->reader_threads_lock().lock(); + reader_list_->reader_threads_lock().unlock(); sched_yield(); nonBlock = true; } @@ -152,29 +137,29 @@ bool LogReader::onDataAvailable(SocketClient* cli) { bool start_time_set = false; uint64_t last = sequence; auto log_find_start = [pid, logMask, start, &sequence, &start_time_set, - &last](const LogBufferElement* element) -> int { + &last](const LogBufferElement* element) -> FlushToResult { if (pid && pid != element->getPid()) { - return 0; + return FlushToResult::kSkip; } if ((logMask & (1 << element->getLogId())) == 0) { - return 0; + return FlushToResult::kSkip; } if (start == element->getRealTime()) { sequence = element->getSequence(); start_time_set = true; - return -1; + return FlushToResult::kStop; } else { if (start < element->getRealTime()) { sequence = last; start_time_set = true; - return -1; + return FlushToResult::kStop; } last = element->getSequence(); } - return 0; + return FlushToResult::kSkip; }; - logbuf().flushTo(cli, sequence, nullptr, privileged, can_read_security, log_find_start); + log_buffer_->FlushTo(cli, sequence, nullptr, privileged, can_read_security, log_find_start); if (!start_time_set) { if (nonBlock) { @@ -187,42 +172,38 @@ bool LogReader::onDataAvailable(SocketClient* cli) { android::prdebug( "logdr: UID=%d GID=%d PID=%d %c tail=%lu logMask=%x pid=%d " - "start=%" PRIu64 "ns timeout=%" PRIu64 "ns\n", + "start=%" PRIu64 "ns deadline=%" PRIi64 "ns\n", cli->getUid(), cli->getGid(), cli->getPid(), nonBlock ? 'n' : 'b', tail, logMask, - (int)pid, start.nsec(), timeout); + (int)pid, start.nsec(), static_cast(deadline.time_since_epoch().count())); if (start == log_time::EPOCH) { - timeout = 0; + deadline = {}; } - LogReaderThread::wrlock(); - auto entry = - std::make_unique(*this, cli, nonBlock, tail, logMask, pid, start, - sequence, timeout, privileged, can_read_security); + auto lock = std::lock_guard{reader_list_->reader_threads_lock()}; + auto entry = std::make_unique(*this, *reader_list_, cli, nonBlock, tail, + logMask, pid, start, sequence, deadline, + privileged, can_read_security); if (!entry->startReader_Locked()) { - LogReaderThread::unlock(); return false; } // release client and entry reference counts once done cli->incRef(); - mLogbuf.mTimes.emplace_front(std::move(entry)); + reader_list_->reader_threads().emplace_front(std::move(entry)); // Set acceptable upper limit to wait for slow reader processing b/27242723 struct timeval t = { LOGD_SNDTIMEO, 0 }; setsockopt(cli->getSocket(), SOL_SOCKET, SO_SNDTIMEO, (const char*)&t, sizeof(t)); - LogReaderThread::unlock(); - return true; } void LogReader::doSocketDelete(SocketClient* cli) { - LastLogTimes& times = mLogbuf.mTimes; - LogReaderThread::wrlock(); - LastLogTimes::iterator it = times.begin(); - while (it != times.end()) { + auto lock = std::lock_guard{reader_list_->reader_threads_lock()}; + auto it = reader_list_->reader_threads().begin(); + while (it != reader_list_->reader_threads().end()) { LogReaderThread* entry = it->get(); if (entry->client() == cli) { entry->release_Locked(); @@ -230,7 +211,6 @@ void LogReader::doSocketDelete(SocketClient* cli) { } it++; } - LogReaderThread::unlock(); } int LogReader::getLogSocket() { diff --git a/logd/LogReader.h b/logd/LogReader.h index f00cc21cd..7df3f6bb6 100644 --- a/logd/LogReader.h +++ b/logd/LogReader.h @@ -18,6 +18,7 @@ #include +#include "LogReaderList.h" #include "LogReaderThread.h" #define LOGD_SNDTIMEO 32 @@ -25,21 +26,19 @@ class LogBuffer; class LogReader : public SocketListener { - LogBuffer& mLogbuf; + public: + explicit LogReader(LogBuffer* logbuf, LogReaderList* reader_list); - public: - explicit LogReader(LogBuffer* logbuf); - void notifyNewLog(unsigned int logMask); + LogBuffer* log_buffer() const { return log_buffer_; } - LogBuffer& logbuf(void) const { - return mLogbuf; - } - - protected: + protected: virtual bool onDataAvailable(SocketClient* cli); - private: + private: static int getLogSocket(); void doSocketDelete(SocketClient* cli); + + LogBuffer* log_buffer_; + LogReaderList* reader_list_; }; diff --git a/logd/LogReaderList.cpp b/logd/LogReaderList.cpp new file mode 100644 index 000000000..220027b28 --- /dev/null +++ b/logd/LogReaderList.cpp @@ -0,0 +1,33 @@ +/* + * 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 "LogReaderList.h" + +// When we are notified a new log entry is available, inform +// listening sockets who are watching this entry's log id. +void LogReaderList::NotifyNewLog(unsigned int log_mask) const { + auto lock = std::lock_guard{reader_threads_lock_}; + + for (const auto& entry : reader_threads_) { + if (!entry->IsWatchingMultiple(log_mask)) { + continue; + } + if (entry->deadline().time_since_epoch().count() != 0) { + continue; + } + entry->triggerReader_Locked(); + } +} diff --git a/logd/LogReaderList.h b/logd/LogReaderList.h new file mode 100644 index 000000000..0d84aba9a --- /dev/null +++ b/logd/LogReaderList.h @@ -0,0 +1,35 @@ +/* + * 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 "LogReaderThread.h" + +class LogReaderList { + public: + void NotifyNewLog(unsigned int log_mask) const; + + std::list>& reader_threads() { return reader_threads_; } + std::mutex& reader_threads_lock() { return reader_threads_lock_; } + + private: + std::list> reader_threads_; + mutable std::mutex reader_threads_lock_; +}; \ No newline at end of file diff --git a/logd/LogReaderThread.cpp b/logd/LogReaderThread.cpp index 5413c4de1..e58e3ebde 100644 --- a/logd/LogReaderThread.cpp +++ b/logd/LogReaderThread.cpp @@ -27,14 +27,14 @@ using namespace std::placeholders; -pthread_mutex_t LogReaderThread::timesLock = PTHREAD_MUTEX_INITIALIZER; - -LogReaderThread::LogReaderThread(LogReader& reader, SocketClient* client, bool non_block, - unsigned long tail, unsigned int log_mask, pid_t pid, - log_time start_time, uint64_t start, uint64_t timeout, +LogReaderThread::LogReaderThread(LogReader& reader, LogReaderList& reader_list, + SocketClient* client, bool non_block, unsigned long tail, + unsigned int log_mask, pid_t pid, log_time start_time, + uint64_t start, std::chrono::steady_clock::time_point deadline, bool privileged, bool can_read_security_logs) : leading_dropped_(false), reader_(reader), + reader_list_(reader_list), log_mask_(log_mask), pid_(pid), tail_(tail), @@ -43,13 +43,11 @@ LogReaderThread::LogReaderThread(LogReader& reader, SocketClient* client, bool n client_(client), start_time_(start_time), start_(start), + deadline_(deadline), non_block_(non_block), privileged_(privileged), can_read_security_logs_(can_read_security_logs) { - timeout_.tv_sec = timeout / NS_PER_SEC; - timeout_.tv_nsec = timeout % NS_PER_SEC; memset(last_tid_, 0, sizeof(last_tid_)); - pthread_cond_init(&thread_triggered_condition_, nullptr); cleanSkip_Locked(); } @@ -64,36 +62,35 @@ void LogReaderThread::ThreadFunction() { SocketClient* client = client_; - LogBuffer& logbuf = reader_.logbuf(); + LogBuffer& logbuf = *reader_.log_buffer(); leading_dropped_ = true; - wrlock(); + auto lock = std::unique_lock{reader_list_.reader_threads_lock()}; uint64_t start = start_; while (!release_) { - if (timeout_.tv_sec || timeout_.tv_nsec) { - if (pthread_cond_clockwait(&thread_triggered_condition_, ×Lock, CLOCK_MONOTONIC, - &timeout_) == ETIMEDOUT) { - timeout_.tv_sec = 0; - timeout_.tv_nsec = 0; + if (deadline_.time_since_epoch().count() != 0) { + if (thread_triggered_condition_.wait_until(lock, deadline_) == + std::cv_status::timeout) { + deadline_ = {}; } if (release_) { break; } } - unlock(); + lock.unlock(); if (tail_) { - logbuf.flushTo(client, start, nullptr, privileged_, can_read_security_logs_, + logbuf.FlushTo(client, start, nullptr, privileged_, can_read_security_logs_, std::bind(&LogReaderThread::FilterFirstPass, this, _1)); leading_dropped_ = true; // TODO: Likely a bug, if leading_dropped_ was not true before calling // flushTo(), then it should not be reset to true after. } - start = logbuf.flushTo(client, start, last_tid_, privileged_, can_read_security_logs_, + start = logbuf.FlushTo(client, start, last_tid_, privileged_, can_read_security_logs_, std::bind(&LogReaderThread::FilterSecondPass, this, _1)); // We only ignore entries before the original start time for the first flushTo(), if we @@ -105,7 +102,7 @@ void LogReaderThread::ThreadFunction() { start_time_.tv_sec = 0; start_time_.tv_nsec = 0; - wrlock(); + lock.lock(); if (start == LogBufferElement::FLUSH_ERROR) { break; @@ -119,35 +116,30 @@ void LogReaderThread::ThreadFunction() { cleanSkip_Locked(); - if (!timeout_.tv_sec && !timeout_.tv_nsec) { - pthread_cond_wait(&thread_triggered_condition_, ×Lock); + if (deadline_.time_since_epoch().count() == 0) { + thread_triggered_condition_.wait(lock); } } - LogReader& reader = reader_; - reader.release(client); - + reader_.release(client); client->decRef(); - LastLogTimes& times = reader.logbuf().mTimes; - auto it = std::find_if(times.begin(), times.end(), + auto& log_reader_threads = reader_list_.reader_threads(); + auto it = std::find_if(log_reader_threads.begin(), log_reader_threads.end(), [this](const auto& other) { return other.get() == this; }); - if (it != times.end()) { - times.erase(it); + if (it != log_reader_threads.end()) { + log_reader_threads.erase(it); } - - unlock(); } // A first pass to count the number of elements -int LogReaderThread::FilterFirstPass(const LogBufferElement* element) { - LogReaderThread::wrlock(); +FlushToResult LogReaderThread::FilterFirstPass(const LogBufferElement* element) { + auto lock = std::lock_guard{reader_list_.reader_threads_lock()}; if (leading_dropped_) { if (element->getDropped()) { - LogReaderThread::unlock(); - return false; + return FlushToResult::kSkip; } leading_dropped_ = false; } @@ -161,48 +153,46 @@ int LogReaderThread::FilterFirstPass(const LogBufferElement* element) { ++count_; } - LogReaderThread::unlock(); - - return false; + return FlushToResult::kSkip; } // A second pass to send the selected elements -int LogReaderThread::FilterSecondPass(const LogBufferElement* element) { - LogReaderThread::wrlock(); +FlushToResult LogReaderThread::FilterSecondPass(const LogBufferElement* element) { + auto lock = std::lock_guard{reader_list_.reader_threads_lock()}; start_ = element->getSequence(); if (skip_ahead_[element->getLogId()]) { skip_ahead_[element->getLogId()]--; - goto skip; + return FlushToResult::kSkip; } if (leading_dropped_) { if (element->getDropped()) { - goto skip; + return FlushToResult::kSkip; } leading_dropped_ = false; } // Truncate to close race between first and second pass if (non_block_ && tail_ && index_ >= count_) { - goto stop; + return FlushToResult::kStop; } if (!IsWatching(element->getLogId())) { - goto skip; + return FlushToResult::kSkip; } if (pid_ && pid_ != element->getPid()) { - goto skip; + return FlushToResult::kSkip; } if (start_time_ != log_time::EPOCH && element->getRealTime() <= start_time_) { - goto skip; + return FlushToResult::kSkip; } if (release_) { - goto stop; + return FlushToResult::kStop; } if (!tail_) { @@ -212,7 +202,7 @@ int LogReaderThread::FilterSecondPass(const LogBufferElement* element) { ++index_; if (count_ > tail_ && index_ <= (count_ - tail_)) { - goto skip; + return FlushToResult::kSkip; } if (!non_block_) { @@ -221,18 +211,9 @@ int LogReaderThread::FilterSecondPass(const LogBufferElement* element) { ok: if (!skip_ahead_[element->getLogId()]) { - LogReaderThread::unlock(); - return true; + return FlushToResult::kWrite; } - // FALLTHRU - -skip: - LogReaderThread::unlock(); - return false; - -stop: - LogReaderThread::unlock(); - return -1; + return FlushToResult::kSkip; } void LogReaderThread::cleanSkip_Locked(void) { diff --git a/logd/LogReaderThread.h b/logd/LogReaderThread.h index 39a8b63cb..f828b6ec9 100644 --- a/logd/LogReaderThread.h +++ b/logd/LogReaderThread.h @@ -21,31 +21,31 @@ #include #include +#include +#include #include #include #include #include +#include "LogBuffer.h" + class LogReader; class LogBufferElement; +class LogReaderList; class LogReaderThread { - static pthread_mutex_t timesLock; - public: - LogReaderThread(LogReader& reader, SocketClient* client, bool non_block, unsigned long tail, - unsigned int log_mask, pid_t pid, log_time start_time, uint64_t sequence, - uint64_t timeout, bool privileged, bool can_read_security_logs); - - // Protect List manipulations - static void wrlock() { pthread_mutex_lock(×Lock); } - static void rdlock() { pthread_mutex_lock(×Lock); } - static void unlock() { pthread_mutex_unlock(×Lock); } + LogReaderThread(LogReader& reader, LogReaderList& reader_list, SocketClient* client, + bool non_block, unsigned long tail, unsigned int log_mask, pid_t pid, + log_time start_time, uint64_t sequence, + std::chrono::steady_clock::time_point deadline, bool privileged, + bool can_read_security_logs); bool startReader_Locked(); - void triggerReader_Locked() { pthread_cond_signal(&thread_triggered_condition_); } + void triggerReader_Locked() { thread_triggered_condition_.notify_all(); } void triggerSkip_Locked(log_id_t id, unsigned int skip) { skip_ahead_[id] = skip; } void cleanSkip_Locked(); @@ -54,7 +54,7 @@ class LogReaderThread { // gracefully shut down the socket. shutdown(client_->getSocket(), SHUT_RDWR); release_ = true; - pthread_cond_signal(&thread_triggered_condition_); + thread_triggered_condition_.notify_all(); } bool IsWatching(log_id_t id) const { return log_mask_ & (1 << id); } @@ -62,13 +62,13 @@ class LogReaderThread { const SocketClient* client() const { return client_; } uint64_t start() const { return start_; } - const timespec& timeout() const { return timeout_; } + std::chrono::steady_clock::time_point deadline() const { return deadline_; } private: void ThreadFunction(); // flushTo filter callbacks - int FilterFirstPass(const LogBufferElement* element); - int FilterSecondPass(const LogBufferElement* element); + FlushToResult FilterFirstPass(const LogBufferElement* element); + FlushToResult FilterSecondPass(const LogBufferElement* element); // Set to true to cause the thread to end and the LogReaderThread to delete itself. bool release_ = false; @@ -77,10 +77,12 @@ class LogReaderThread { bool leading_dropped_; // Condition variable for waking the reader thread if there are messages pending for its client. - pthread_cond_t thread_triggered_condition_; + std::condition_variable thread_triggered_condition_; // Reference to the parent thread that manages log reader sockets. LogReader& reader_; + // Reference to the parent list that shares its lock with each instance + LogReaderList& reader_list_; // A mask of the logs buffers that are read by this reader. const unsigned int log_mask_; // If set to non-zero, only pids equal to this are read by the reader. @@ -110,9 +112,9 @@ class LogReaderThread { log_time start_time_; // The point from which the reader will read logs once awoken. uint64_t start_; - // CLOCK_MONOTONIC based timeout used for log wrapping. If this timeout expires before logs + // CLOCK_MONOTONIC based deadline used for log wrapping. If this deadline expires before logs // wrap, then wake up and send the logs to the reader anyway. - timespec timeout_; + std::chrono::steady_clock::time_point deadline_; // If this reader is 'dumpAndClose' and will disconnect once it has read its intended logs. const bool non_block_; @@ -122,5 +124,3 @@ class LogReaderThread { // Whether or not this reader can read security logs. See CanReadSecurityLogs(). bool can_read_security_logs_; }; - -typedef std::list> LastLogTimes; diff --git a/logd/fuzz/Android.bp b/logd/fuzz/Android.bp index 299242db6..f65fbdfe6 100644 --- a/logd/fuzz/Android.bp +++ b/logd/fuzz/Android.bp @@ -25,6 +25,7 @@ cc_fuzz { "liblog", "liblogd", "libcutils", + "libsysutils", ], cflags: ["-Werror"], } diff --git a/logd/fuzz/log_buffer_log_fuzzer.cpp b/logd/fuzz/log_buffer_log_fuzzer.cpp index 58610c490..8f90f5068 100644 --- a/logd/fuzz/log_buffer_log_fuzzer.cpp +++ b/logd/fuzz/log_buffer_log_fuzzer.cpp @@ -15,7 +15,8 @@ */ #include -#include "../LogBuffer.h" +#include "../ChattyLogBuffer.h" +#include "../LogReaderList.h" #include "../LogReaderThread.h" #include "../LogStatistics.h" @@ -71,7 +72,7 @@ int write_log_messages(const uint8_t** pdata, size_t* data_left, LogBuffer* log_ // Other elements not in enum. log_id_t log_id = static_cast(unsigned(logInput->log_id) % (LOG_ID_MAX + 1)); - log_buffer->log(log_id, logInput->realtime, logInput->uid, logInput->pid, logInput->tid, msg, + log_buffer->Log(log_id, logInput->realtime, logInput->uid, logInput->pid, logInput->tid, msg, sizeof(uint32_t) + msg_length + 1); stats->Format(logInput->uid, logInput->pid, logInput->log_mask); *pdata = data; @@ -95,25 +96,25 @@ extern "C" int LLVMFuzzerTestOneInput(const uint8_t* data, size_t size) { return 0; } - LastLogTimes times; + LogReaderList reader_list; LogTags tags; PruneList prune_list; LogStatistics stats(true); - LogBuffer log_buffer(×, &tags, &prune_list, &stats); + LogBuffer* log_buffer = new ChattyLogBuffer(&reader_list, &tags, &prune_list, &stats); size_t data_left = size; const uint8_t** pdata = &data; prune_list.init(nullptr); // We want to get pruning code to get called. - log_id_for_each(i) { log_buffer.setSize(i, 10000); } + log_id_for_each(i) { log_buffer->SetSize(i, 10000); } while (data_left >= sizeof(LogInput) + 2 * sizeof(uint8_t)) { - if (!write_log_messages(pdata, &data_left, &log_buffer, &stats)) { + if (!write_log_messages(pdata, &data_left, log_buffer, &stats)) { return 0; } } - log_id_for_each(i) { log_buffer.clear(i); } + log_id_for_each(i) { log_buffer->Clear(i, 0); } return 0; } } // namespace android diff --git a/logd/main.cpp b/logd/main.cpp index cd8b19597..6e1144b67 100644 --- a/logd/main.cpp +++ b/logd/main.cpp @@ -47,6 +47,7 @@ #include #include +#include "ChattyLogBuffer.h" #include "CommandListener.h" #include "LogAudit.h" #include "LogBuffer.h" @@ -271,8 +272,10 @@ int main(int argc, char* argv[]) { // A cache of event log tags LogTags log_tags; + // Pruning configuration. PruneList prune_list; + // Partial (required for chatty) or full logging statistics. bool enable_full_log_statistics = __android_logger_property_get_bool( "logd.statistics", BOOL_DEFAULT_TRUE | BOOL_DEFAULT_FLAG_PERSIST | @@ -282,18 +285,15 @@ int main(int argc, char* argv[]) { // Serves the purpose of managing the last logs times read on a // socket connection, and as a reader lock on a range of log // entries. - - LastLogTimes* times = new LastLogTimes(); + LogReaderList reader_list; // LogBuffer is the object which is responsible for holding all // log entries. - - LogBuffer* logBuf = new LogBuffer(times, &log_tags, &prune_list, &log_statistics); + LogBuffer* logBuf = new ChattyLogBuffer(&reader_list, &log_tags, &prune_list, &log_statistics); // LogReader listens on /dev/socket/logdr. When a client // connects, log entries in the LogBuffer are written to the client. - - LogReader* reader = new LogReader(logBuf); + LogReader* reader = new LogReader(logBuf, &reader_list); if (reader->startListener()) { return EXIT_FAILURE; } @@ -301,15 +301,13 @@ int main(int argc, char* argv[]) { // LogListener listens on /dev/socket/logdw for client // initiated log messages. New log entries are added to LogBuffer // and LogReader is notified to send updates to connected clients. - - LogListener* swl = new LogListener(logBuf, reader); + LogListener* swl = new LogListener(logBuf); if (!swl->StartListener()) { return EXIT_FAILURE; } // Command listener listens on /dev/socket/logd for incoming logd // administrative commands. - CommandListener* cl = new CommandListener(logBuf, &log_tags, &prune_list, &log_statistics); if (cl->startListener()) { return EXIT_FAILURE; @@ -318,26 +316,22 @@ int main(int argc, char* argv[]) { // LogAudit listens on NETLINK_AUDIT socket for selinux // initiated log messages. New log entries are added to LogBuffer // and LogReader is notified to send updates to connected clients. - LogAudit* al = nullptr; if (auditd) { - al = new LogAudit( - logBuf, reader, - __android_logger_property_get_bool("ro.logd.auditd.dmesg", BOOL_DEFAULT_TRUE) - ? fdDmesg - : -1, - &log_statistics); + int dmesg_fd = __android_logger_property_get_bool("ro.logd.auditd.dmesg", BOOL_DEFAULT_TRUE) + ? fdDmesg + : -1; + al = new LogAudit(logBuf, dmesg_fd, &log_statistics); } LogKlog* kl = nullptr; if (klogd) { - kl = new LogKlog(logBuf, reader, fdDmesg, fdPmesg, al != nullptr, &log_statistics); + kl = new LogKlog(logBuf, fdDmesg, fdPmesg, al != nullptr, &log_statistics); } readDmesg(al, kl); // failure is an option ... messages are in dmesg (required by standard) - if (kl && kl->startListener()) { delete kl; }