/* * 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 #include "LogBufferElement.h" #include "LogSize.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, GetBufferSizeFromProperties(i))) { SetSize(i, kLogBufferMinSize); } } // Release any sleeping reader threads to dump their current content. auto lock = std::lock_guard{logd_lock}; for (const auto& reader_thread : reader_list_->reader_threads()) { reader_thread->TriggerReader(); } } std::list::iterator SimpleLogBuffer::GetOldest(log_id_t log_id) { auto it = logs().begin(); if (oldest_[log_id]) { it = *oldest_[log_id]; } while (it != logs().end() && it->log_id() != 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 (IsBinary(log_id)) { int32_t numeric_tag = MsgToTag(msg, len); 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{logd_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.log_id(); logs_.emplace_back(std::move(elem)); stats_->Add(logs_.back().ToLogStatisticsElement()); MaybePrune(log_id); reader_list_->NotifyNewLog(1 << log_id); } // These extra parameters are only required for chatty, but since they're a no-op for // SimpleLogBuffer, it's easier to include them here, then to duplicate FlushTo() for // ChattyLogBuffer. class ChattyFlushToState : public FlushToState { public: ChattyFlushToState(uint64_t start, LogMask log_mask) : FlushToState(start, log_mask) {} pid_t* last_tid() { return last_tid_; } bool drop_chatty_messages() const { return drop_chatty_messages_; } void set_drop_chatty_messages(bool value) { drop_chatty_messages_ = value; } private: pid_t last_tid_[LOG_ID_MAX] = {}; bool drop_chatty_messages_ = true; }; std::unique_ptr SimpleLogBuffer::CreateFlushToState(uint64_t start, LogMask log_mask) { return std::make_unique(start, log_mask); } bool SimpleLogBuffer::FlushTo( LogWriter* writer, FlushToState& abstract_state, const std::function& filter) { auto& state = reinterpret_cast(abstract_state); std::list::iterator it; if (state.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->sequence() == state.start()) { break; } else if (it->sequence() < state.start()) { it++; break; } } } for (; it != logs_.end(); ++it) { LogBufferElement& element = *it; state.set_start(element.sequence()); if (!writer->privileged() && element.uid() != writer->uid()) { continue; } if (((1 << element.log_id()) & state.log_mask()) == 0) { continue; } if (filter) { FilterResult ret = filter(element.log_id(), element.pid(), element.sequence(), element.realtime()); if (ret == FilterResult::kSkip) { continue; } if (ret == FilterResult::kStop) { break; } } // drop_chatty_messages is initialized to true, so if the first message that we attempt to // flush is a chatty message, we drop it. Once we see a non-chatty message it gets set to // false to let further chatty messages be printed. if (state.drop_chatty_messages()) { if (element.dropped_count() != 0) { continue; } state.set_drop_chatty_messages(false); } bool same_tid = state.last_tid()[element.log_id()] == element.tid(); // 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. state.last_tid()[element.log_id()] = (element.dropped_count() && !same_tid) ? 0 : element.tid(); logd_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 if (!element.FlushTo(writer, stats_, same_tid)) { logd_lock.lock(); return false; } logd_lock.lock(); } state.set_start(state.start() + 1); return true; } bool SimpleLogBuffer::Clear(log_id_t id, uid_t uid) { // Try three times to clear, then disconnect the readers and try one final time. for (int retry = 0; retry < 3; ++retry) { { auto lock = std::lock_guard{logd_lock}; if (Prune(id, ULONG_MAX, uid)) { return true; } } sleep(1); } // Check if it is still busy after the sleep, we try to 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. bool busy = false; { auto lock = std::lock_guard{logd_lock}; busy = !Prune(id, 1, uid); } // It is still busy, disconnect all readers. if (busy) { auto lock = std::lock_guard{logd_lock}; for (const auto& reader_thread : reader_list_->reader_threads()) { if (reader_thread->IsWatching(id)) { LOG(WARNING) << "Kicking blocked reader, " << reader_thread->name() << ", from LogBuffer::clear()"; reader_thread->Release(); } } } auto lock = std::lock_guard{logd_lock}; return Prune(id, ULONG_MAX, uid); } // get the total space allocated to "id" size_t SimpleLogBuffer::GetSize(log_id_t id) { auto lock = std::lock_guard{logd_lock}; size_t retval = max_size_[id]; return retval; } // set the total space allocated to "id" bool SimpleLogBuffer::SetSize(log_id_t id, size_t size) { // Reasonable limits ... if (!IsValidBufferSize(size)) { return false; } auto lock = std::lock_guard{logd_lock}; max_size_[id] = size; return true; } 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) { // 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.log_id() != id) { ++it; continue; } if (caller_uid != 0 && element.uid() != caller_uid) { ++it; continue; } if (oldest && oldest->start() <= element.sequence()) { KickReader(oldest, id, prune_rows); return false; } stats_->Subtract(element.ToLogStatisticsElement()); it = Erase(it); if (--prune_rows == 0) { return true; } } return true; } std::list::iterator SimpleLogBuffer::Erase( std::list::iterator it) { bool oldest_is_it[LOG_ID_MAX]; log_id_for_each(i) { oldest_is_it[i] = oldest_[i] && it == *oldest_[i]; } it = logs_.erase(it); log_id_for_each(i) { if (oldest_is_it[i]) { if (__predict_false(it == logs().end())) { oldest_[i] = std::nullopt; } else { oldest_[i] = it; // Store the next iterator even if it does not correspond to // the same log_id, as a starting point for GetOldest(). } } } return it; } // If the selected reader is blocking our pruning progress, decide on // what kind of mitigation is necessary to unblock the situation. void SimpleLogBuffer::KickReader(LogReaderThread* reader, log_id_t id, unsigned long prune_rows) { if (stats_->Sizes(id) > (2 * max_size_[id])) { // +100% // A misbehaving or slow reader has its connection // dropped if we hit too much memory pressure. LOG(WARNING) << "Kicking blocked reader, " << reader->name() << ", from LogBuffer::kickMe()"; reader->Release(); } 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(); } else { // tell slow reader to skip entries to catch up LOG(WARNING) << "Skipping " << prune_rows << " entries from slow reader, " << reader->name() << ", from LogBuffer::kickMe()"; reader->TriggerSkip(id, prune_rows); } }