logd/SimpleLogBuffer.cpp - platform/system/logging - Gitiles

 /*
  * 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 <android-base/logging.h>

 #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<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->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<FlushToState> SimpleLogBuffer::CreateFlushToState(uint64_t start,
                                                                   LogMask log_mask) {
     return std::make_unique<ChattyFlushToState>(start, log_mask);
 }

 bool SimpleLogBuffer::FlushTo(
         LogWriter* writer, FlushToState& abstract_state,
         const std::function<FilterResult(log_id_t log_id, pid_t pid, uint64_t sequence,
                                          log_time realtime)>& filter) {
     auto& state = reinterpret_cast<ChattyFlushToState&>(abstract_state);

     std::list<LogBufferElement>::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<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.
         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);
     }
 }
	/*
	* 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 <android-base/logging.h>

	#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<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->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<FlushToState> SimpleLogBuffer::CreateFlushToState(uint64_t start,
	LogMask log_mask) {
	return std::make_unique<ChattyFlushToState>(start, log_mask);
	}

	bool SimpleLogBuffer::FlushTo(
	LogWriter* writer, FlushToState& abstract_state,
	const std::function<FilterResult(log_id_t log_id, pid_t pid, uint64_t sequence,
	log_time realtime)>& filter) {
	auto& state = reinterpret_cast<ChattyFlushToState&>(abstract_state);

	std::list<LogBufferElement>::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<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.
	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);
	}
	}