Merge "logd: move leading_dropped logic into FlushTo()" (a8b8d108) · Commits · e / os / android_system_core

logd/ChattyLogBufferTest.cpp

+130 −0

Original line number	Diff line number	Diff line
		@@ -202,4 +202,134 @@ TEST_P(ChattyLogBufferTest, deduplication_liblog) {
		CompareLogMessages(expected_log_messages, read_log_messages);
		};

		TEST_P(ChattyLogBufferTest, no_leading_chatty_simple) {
		auto make_message = [&](uint32_t sec, int32_t pid, uint32_t uid, uint32_t lid, const char* tag,
		const char* msg, bool regex = false) -> LogMessage {
		logger_entry entry = {.pid = pid, .tid = 1, .sec = sec, .nsec = 1, .lid = lid, .uid = uid};
		std::string message;
		message.push_back(ANDROID_LOG_INFO);
		message.append(tag);
		message.push_back('\0');
		message.append(msg);
		message.push_back('\0');
		return {entry, message, regex};
		};

		// clang-format off
		std::vector<LogMessage> log_messages = {
		make_message(1, 1, 1, LOG_ID_MAIN, "test_tag", "duplicate1"),
		make_message(2, 2, 2, LOG_ID_SYSTEM, "test_tag", "duplicate2"),
		make_message(3, 2, 2, LOG_ID_SYSTEM, "test_tag", "duplicate2"),
		make_message(4, 2, 2, LOG_ID_SYSTEM, "test_tag", "duplicate2"),
		make_message(6, 2, 2, LOG_ID_SYSTEM, "test_tag", "not duplicate2"),
		make_message(7, 1, 1, LOG_ID_MAIN, "test_tag", "duplicate1"),
		make_message(8, 1, 1, LOG_ID_MAIN, "test_tag", "duplicate1"),
		make_message(9, 1, 1, LOG_ID_MAIN, "test_tag", "duplicate1"),
		make_message(10, 1, 1, LOG_ID_MAIN, "test_tag", "not duplicate1"),
		};
		// clang-format on
		FixupMessages(&log_messages);
		LogMessages(log_messages);

		// After logging log_messages, the below is what should be in the buffer:
		// PID=1, LOG_ID_MAIN duplicate1
		// [1] PID=2, LOG_ID_SYSTEM duplicate2
		// PID=2, LOG_ID_SYSTEM chatty drop
		// PID=2, LOG_ID_SYSTEM duplicate2
		// PID=2, LOG_ID_SYSTEM not duplicate2
		// [2] PID=1, LOG_ID_MAIN chatty drop
		// [3] PID=1, LOG_ID_MAIN duplicate1
		// PID=1, LOG_ID_MAIN not duplicate1

		// We then read from the 2nd sequence number, starting from log message [1], but filtering out
		// everything but PID=1, which results in us starting with log message [2], which is a chatty
		// drop. Code prior to this test case would erroneously print it. The intended behavior that
		// this test checks prints logs starting from log message [3].

		// clang-format off
		std::vector<LogMessage> expected_log_messages = {
		make_message(9, 1, 1, LOG_ID_MAIN, "test_tag", "duplicate1"),
		make_message(10, 1, 1, LOG_ID_MAIN, "test_tag", "not duplicate1"),
		};
		FixupMessages(&expected_log_messages);
		// clang-format on

		std::vector<LogMessage> read_log_messages;
		bool released = false;
		{
		auto lock = std::unique_lock{reader_list_.reader_threads_lock()};
		std::unique_ptr<LogWriter> test_writer(new TestWriter(&read_log_messages, &released));
		std::unique_ptr<LogReaderThread> log_reader(
		new LogReaderThread(log_buffer_.get(), &reader_list_, std::move(test_writer), true,
		0, ~0, 1, {}, 2, {}));
		reader_list_.reader_threads().emplace_back(std::move(log_reader));
		}

		while (!released) {
		usleep(5000);
		}

		CompareLogMessages(expected_log_messages, read_log_messages);
		}

		TEST_P(ChattyLogBufferTest, no_leading_chatty_tail) {
		auto make_message = [&](uint32_t sec, const char* tag, const char* msg,
		bool regex = false) -> LogMessage {
		logger_entry entry = {
		.pid = 1, .tid = 1, .sec = sec, .nsec = 1, .lid = LOG_ID_MAIN, .uid = 0};
		std::string message;
		message.push_back(ANDROID_LOG_INFO);
		message.append(tag);
		message.push_back('\0');
		message.append(msg);
		message.push_back('\0');
		return {entry, message, regex};
		};

		// clang-format off
		std::vector<LogMessage> log_messages = {
		make_message(1, "test_tag", "duplicate"),
		make_message(2, "test_tag", "duplicate"),
		make_message(3, "test_tag", "duplicate"),
		make_message(4, "test_tag", "not_duplicate"),
		};
		// clang-format on
		FixupMessages(&log_messages);
		LogMessages(log_messages);

		// After logging log_messages, the below is what should be in the buffer:
		// "duplicate"
		// chatty
		// "duplicate"
		// "not duplicate"

		// We then read the tail 3 messages expecting there to not be a chatty message, meaning that we
		// should only see the last two messages.

		// clang-format off
		std::vector<LogMessage> expected_log_messages = {
		make_message(3, "test_tag", "duplicate"),
		make_message(4, "test_tag", "not_duplicate"),
		};
		FixupMessages(&expected_log_messages);
		// clang-format on

		std::vector<LogMessage> read_log_messages;
		bool released = false;
		{
		auto lock = std::unique_lock{reader_list_.reader_threads_lock()};
		std::unique_ptr<LogWriter> test_writer(new TestWriter(&read_log_messages, &released));
		std::unique_ptr<LogReaderThread> log_reader(
		new LogReaderThread(log_buffer_.get(), &reader_list_, std::move(test_writer), true,
		3, ~0, 0, {}, 1, {}));
		reader_list_.reader_threads().emplace_back(std::move(log_reader));
		}

		while (!released) {
		usleep(5000);
		}

		CompareLogMessages(expected_log_messages, read_log_messages);
		}

		INSTANTIATE_TEST_CASE_P(ChattyLogBufferTests, ChattyLogBufferTest, testing::Values("chatty"));

logd/LogBuffer.h

+4 −4

Original line number	Diff line number	Diff line
		@@ -62,10 +62,10 @@ class LogBuffer {
		const char* msg, uint16_t len) = 0;

		virtual std::unique_ptr<FlushToState> CreateFlushToState(uint64_t start, LogMask log_mask) = 0;
		virtual bool FlushTo(LogWriter* writer, FlushToState& state,
		const std::function<FilterResult(log_id_t log_id, pid_t pid,
		uint64_t sequence, log_time realtime,
		uint16_t dropped_count)>& filter) = 0;
		virtual bool FlushTo(
		LogWriter* writer, FlushToState& state,
		const std::function<FilterResult(log_id_t log_id, pid_t pid, uint64_t sequence,
		log_time realtime)>& filter) = 0;

		virtual bool Clear(log_id_t id, uid_t uid) = 0;
		virtual unsigned long GetSize(log_id_t id) = 0;

logd/LogBufferTest.cpp

+1 −1

Original line number	Diff line number	Diff line
		@@ -119,7 +119,7 @@ static std::string CompareMessages(const std::string& expected, const std::strin
		}
		}

		if (diff_index < 10) {
		if (diff_index < 80) {
		auto expected_short = MakePrintable(expected);
		auto result_short = MakePrintable(result);
		return StringPrintf("msg: expected '%s' vs '%s'", expected_short.c_str(),

logd/LogReader.cpp

+1 −1

Original line number	Diff line number	Diff line
		@@ -172,7 +172,7 @@ bool LogReader::onDataAvailable(SocketClient* cli) {
		uint64_t last = sequence;
		auto log_find_start = [pid, start, &sequence, &start_time_set, &last](
		log_id_t, pid_t element_pid, uint64_t element_sequence,
		log_time element_realtime, uint16_t) -> FilterResult {
		log_time element_realtime) -> FilterResult {
		if (pid && pid != element_pid) {
		return FilterResult::kSkip;
		}

logd/LogReaderThread.cpp

+9 −32

Original line number	Diff line number	Diff line
		@@ -35,7 +35,6 @@ LogReaderThread::LogReaderThread(LogBuffer* log_buffer, LogReaderList* reader_li
		: log_buffer_(log_buffer),
		reader_list_(reader_list),
		writer_(std::move(writer)),
		leading_dropped_(false),
		pid_(pid),
		tail_(tail),
		count_(0),
		@@ -52,8 +51,6 @@ LogReaderThread::LogReaderThread(LogBuffer* log_buffer, LogReaderList* reader_li
		void LogReaderThread::ThreadFunction() {
		prctl(PR_SET_NAME, "logd.reader.per");

		leading_dropped_ = true;

		auto lock = std::unique_lock{reader_list_->reader_threads_lock()};

		while (!release_) {
		@@ -72,21 +69,16 @@ void LogReaderThread::ThreadFunction() {
		if (tail_) {
		auto first_pass_state = log_buffer_->CreateFlushToState(flush_to_state_->start(),
		flush_to_state_->log_mask());
		log_buffer_->FlushTo(writer_.get(), *first_pass_state,
		[this](log_id_t log_id, pid_t pid, uint64_t sequence,
		log_time realtime, uint16_t dropped_count) {
		return FilterFirstPass(log_id, pid, sequence, realtime,
		dropped_count);
		log_buffer_->FlushTo(
		writer_.get(), *first_pass_state,
		[this](log_id_t log_id, pid_t pid, uint64_t sequence, log_time realtime) {
		return FilterFirstPass(log_id, pid, sequence, realtime);
		});
		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.
		}
		bool flush_success = log_buffer_->FlushTo(
		writer_.get(), *flush_to_state_,
		[this](log_id_t log_id, pid_t pid, uint64_t sequence, log_time realtime,
		uint16_t dropped_count) {
		return FilterSecondPass(log_id, pid, sequence, realtime, dropped_count);
		[this](log_id_t log_id, pid_t pid, uint64_t sequence, log_time realtime) {
		return FilterSecondPass(log_id, pid, sequence, realtime);
		});

		// We only ignore entries before the original start time for the first flushTo(), if we
		@@ -127,17 +119,9 @@ void LogReaderThread::ThreadFunction() {
		}

		// A first pass to count the number of elements
		FilterResult LogReaderThread::FilterFirstPass(log_id_t, pid_t pid, uint64_t, log_time realtime,
		uint16_t dropped_count) {
		FilterResult LogReaderThread::FilterFirstPass(log_id_t, pid_t pid, uint64_t, log_time realtime) {
		auto lock = std::lock_guard{reader_list_->reader_threads_lock()};

		if (leading_dropped_) {
		if (dropped_count) {
		return FilterResult::kSkip;
		}
		leading_dropped_ = false;
		}

		if ((!pid_ \|\| pid_ == pid) && (start_time_ == log_time::EPOCH \|\| start_time_ <= realtime)) {
		++count_;
		}
		@@ -147,7 +131,7 @@ FilterResult LogReaderThread::FilterFirstPass(log_id_t, pid_t pid, uint64_t, log

		// A second pass to send the selected elements
		FilterResult LogReaderThread::FilterSecondPass(log_id_t log_id, pid_t pid, uint64_t,
		log_time realtime, uint16_t dropped_count) {
		log_time realtime) {
		auto lock = std::lock_guard{reader_list_->reader_threads_lock()};

		if (skip_ahead_[log_id]) {
		@@ -155,13 +139,6 @@ FilterResult LogReaderThread::FilterSecondPass(log_id_t log_id, pid_t pid, uint6
		return FilterResult::kSkip;
		}

		if (leading_dropped_) {
		if (dropped_count) {
		return FilterResult::kSkip;
		}
		leading_dropped_ = false;
		}

		// Truncate to close race between first and second pass
		if (non_block_ && tail_ && index_ >= count_) {
		return FilterResult::kStop;