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;