From b3e163399a9038175d46c9dbd9262d009e87ceb6 Mon Sep 17 00:00:00 2001 From: Tom Cherry Date: Thu, 28 May 2020 20:02:42 -0700 Subject: [PATCH] logd: move leading_dropped logic into FlushTo() This logic isn't generic, so it should not be in the generic LogReaderThread. Moreover, it's currently broken in essentially every case except when filtering by UID, because it runs as in the filter functions before the actual filtering by pid/etc takes place. For example, when filtering by pid, it's possible to get leading chatty messages. The newly added test was failing previously but is fixed by this change. It's fundamentally broken in the tail case. Take this example: 1: Normal message 2: Chatty message 3: Normal message 4: Normal message If you read that log buffer with a tail value of 3, there are three possible outcomes: 1) Messages #2-4, however this would include a leading chatty message, which is not allowed. 2) Messages #3-4, however this is only 2, not 3 messages. 3) Messages #1-4, however this is 4, more than the 3 requested messages. This code chooses 2) as the correct solution, in this case, we don't need to account for leading chatty messages when counting the total logs in the buffer. A test is added for this case as well. Test: new unit test Change-Id: Id02eb81a8e77390aba4f85aac659c6cab498dbcd --- logd/ChattyLogBufferTest.cpp | 130 +++++++++++++++++++++++++++++++++++ logd/LogBuffer.h | 8 +-- logd/LogBufferTest.cpp | 2 +- logd/LogReader.cpp | 2 +- logd/LogReaderThread.cpp | 41 +++-------- logd/LogReaderThread.h | 9 +-- logd/SimpleLogBuffer.cpp | 20 +++++- logd/SimpleLogBuffer.h | 3 +- 8 files changed, 165 insertions(+), 50 deletions(-) diff --git a/logd/ChattyLogBufferTest.cpp b/logd/ChattyLogBufferTest.cpp index 8754b885a..3d9005ab6 100644 --- a/logd/ChattyLogBufferTest.cpp +++ b/logd/ChattyLogBufferTest.cpp @@ -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 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 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 read_log_messages; + bool released = false; + { + auto lock = std::unique_lock{reader_list_.reader_threads_lock()}; + std::unique_ptr test_writer(new TestWriter(&read_log_messages, &released)); + std::unique_ptr 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 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 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 read_log_messages; + bool released = false; + { + auto lock = std::unique_lock{reader_list_.reader_threads_lock()}; + std::unique_ptr test_writer(new TestWriter(&read_log_messages, &released)); + std::unique_ptr 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")); diff --git a/logd/LogBuffer.h b/logd/LogBuffer.h index a3ac683f8..c5d333a9e 100644 --- a/logd/LogBuffer.h +++ b/logd/LogBuffer.h @@ -62,10 +62,10 @@ class LogBuffer { const char* msg, uint16_t len) = 0; virtual std::unique_ptr CreateFlushToState(uint64_t start, LogMask log_mask) = 0; - virtual bool FlushTo(LogWriter* writer, FlushToState& state, - const std::function& filter) = 0; + virtual bool FlushTo( + LogWriter* writer, FlushToState& state, + const std::function& filter) = 0; virtual bool Clear(log_id_t id, uid_t uid) = 0; virtual unsigned long GetSize(log_id_t id) = 0; diff --git a/logd/LogBufferTest.cpp b/logd/LogBufferTest.cpp index bc01c805e..ced4a215f 100644 --- a/logd/LogBufferTest.cpp +++ b/logd/LogBufferTest.cpp @@ -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(), diff --git a/logd/LogReader.cpp b/logd/LogReader.cpp index 44bafb9b8..42d4574e9 100644 --- a/logd/LogReader.cpp +++ b/logd/LogReader.cpp @@ -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; } diff --git a/logd/LogReaderThread.cpp b/logd/LogReaderThread.cpp index c6e60feff..dc8582d1a 100644 --- a/logd/LogReaderThread.cpp +++ b/logd/LogReaderThread.cpp @@ -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); - }); - 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. + 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); + }); } 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; diff --git a/logd/LogReaderThread.h b/logd/LogReaderThread.h index f288d68cc..bf70b944e 100644 --- a/logd/LogReaderThread.h +++ b/logd/LogReaderThread.h @@ -64,10 +64,8 @@ class LogReaderThread { private: void ThreadFunction(); // flushTo filter callbacks - FilterResult FilterFirstPass(log_id_t log_id, pid_t pid, uint64_t sequence, log_time realtime, - uint16_t dropped_count); - FilterResult FilterSecondPass(log_id_t log_id, pid_t pid, uint64_t sequence, log_time realtime, - uint16_t dropped_count); + FilterResult FilterFirstPass(log_id_t log_id, pid_t pid, uint64_t sequence, log_time realtime); + FilterResult FilterSecondPass(log_id_t log_id, pid_t pid, uint64_t sequence, log_time realtime); std::condition_variable thread_triggered_condition_; LogBuffer* log_buffer_; @@ -76,9 +74,6 @@ class LogReaderThread { // Set to true to cause the thread to end and the LogReaderThread to delete itself. bool release_ = false; - // Indicates whether or not 'leading' (first logs seen starting from start_) 'dropped' (chatty) - // messages should be ignored. - bool leading_dropped_; // If set to non-zero, only pids equal to this are read by the reader. const pid_t pid_; diff --git a/logd/SimpleLogBuffer.cpp b/logd/SimpleLogBuffer.cpp index 79ce06971..5ab8e0983 100644 --- a/logd/SimpleLogBuffer.cpp +++ b/logd/SimpleLogBuffer.cpp @@ -119,8 +119,12 @@ class ChattyFlushToState : public FlushToState { 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, @@ -131,7 +135,7 @@ std::unique_ptr SimpleLogBuffer::CreateFlushToState(uint64_t start bool SimpleLogBuffer::FlushTo( LogWriter* writer, FlushToState& abstract_state, const std::function& filter) { + log_time realtime)>& filter) { auto shared_lock = SharedLock{lock_}; auto& state = reinterpret_cast(abstract_state); @@ -169,8 +173,8 @@ bool SimpleLogBuffer::FlushTo( } if (filter) { - FilterResult ret = filter(element.log_id(), element.pid(), element.sequence(), - element.realtime(), element.dropped_count()); + FilterResult ret = + filter(element.log_id(), element.pid(), element.sequence(), element.realtime()); if (ret == FilterResult::kSkip) { continue; } @@ -179,6 +183,16 @@ bool SimpleLogBuffer::FlushTo( } } + // 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 diff --git a/logd/SimpleLogBuffer.h b/logd/SimpleLogBuffer.h index a2ab881ee..2172507a3 100644 --- a/logd/SimpleLogBuffer.h +++ b/logd/SimpleLogBuffer.h @@ -38,8 +38,7 @@ class SimpleLogBuffer : public LogBuffer { std::unique_ptr CreateFlushToState(uint64_t start, LogMask log_mask) override; bool FlushTo(LogWriter* writer, FlushToState& state, const std::function& - filter) override; + log_time realtime)>& filter) override; bool Clear(log_id_t id, uid_t uid) override; unsigned long GetSize(log_id_t id) override;