Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit b3e16339 authored by Tom Cherry's avatar Tom Cherry
Browse files

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
parent 4ab0bc41

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;