Merge "logd: move leading_dropped logic into FlushTo()"
diff --git a/logd/ChattyLogBufferTest.cpp b/logd/ChattyLogBufferTest.cpp
index 8754b88..3d9005a 100644
--- a/logd/ChattyLogBufferTest.cpp
+++ b/logd/ChattyLogBufferTest.cpp
@@ -202,4 +202,134 @@
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"));
diff --git a/logd/LogBuffer.h b/logd/LogBuffer.h
index a3ac683..c5d333a 100644
--- a/logd/LogBuffer.h
+++ b/logd/LogBuffer.h
@@ -62,10 +62,10 @@
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;
diff --git a/logd/LogBufferTest.cpp b/logd/LogBufferTest.cpp
index bc01c80..ced4a21 100644
--- a/logd/LogBufferTest.cpp
+++ b/logd/LogBufferTest.cpp
@@ -119,7 +119,7 @@
}
}
- 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 44bafb9..42d4574 100644
--- a/logd/LogReader.cpp
+++ b/logd/LogReader.cpp
@@ -172,7 +172,7 @@
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 c6e60fe..dc8582d 100644
--- a/logd/LogReaderThread.cpp
+++ b/logd/LogReaderThread.cpp
@@ -35,7 +35,6 @@
: 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 @@
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 @@
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 @@
}
// 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 @@
// 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 @@
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 f288d68..bf70b94 100644
--- a/logd/LogReaderThread.h
+++ b/logd/LogReaderThread.h
@@ -64,10 +64,8 @@
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 @@
// 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 79ce069..5ab8e09 100644
--- a/logd/SimpleLogBuffer.cpp
+++ b/logd/SimpleLogBuffer.cpp
@@ -119,8 +119,12 @@
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,
@@ -131,7 +135,7 @@
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, uint16_t dropped_count)>& filter) {
+ log_time realtime)>& filter) {
auto shared_lock = SharedLock{lock_};
auto& state = reinterpret_cast<ChattyFlushToState&>(abstract_state);
@@ -169,8 +173,8 @@
}
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 @@
}
}
+ // 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 a2ab881..2172507 100644
--- a/logd/SimpleLogBuffer.h
+++ b/logd/SimpleLogBuffer.h
@@ -38,8 +38,7 @@
std::unique_ptr<FlushToState> CreateFlushToState(uint64_t start, LogMask log_mask) override;
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) override;
+ log_time realtime)>& filter) override;
bool Clear(log_id_t id, uid_t uid) override;
unsigned long GetSize(log_id_t id) override;