logd/SerializedLogBufferTest.cpp

/*
 * Copyright (C) 2021 The Android Open Source Project
 *
 * Licensed under the Apache License, Version 2.0 (the "License");
 * you may not use this file except in compliance with the License.
 * You may obtain a copy of the License at
 *
 *      http://www.apache.org/licenses/LICENSE-2.0
 *
 * Unless required by applicable law or agreed to in writing, software
 * distributed under the License is distributed on an "AS IS" BASIS,
 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
 * See the License for the specific language governing permissions and
 * limitations under the License.
 */

#include "SerializedLogBuffer.h"

#include <gtest/gtest.h>
#include <log/log.h>

#include "LogReaderList.h"
#include "LogSize.h"
#include "LogStatistics.h"
#include "LogTags.h"
#include "SerializedLogChunk.h"
#include "SerializedLogEntry.h"

// b/188858988 - Previously, if clearing UID logs erased the back-most chunk, then a chunk that has
// previously been closed for writing will be the back-most chunk in the list. Subsequent calls to
// SerializedLogBuffer::Log() will call SerializedLogChunk::FinishWriting(), which triggered a
// CHECK().
TEST(SerializedLogBuffer, uid_prune_deletes_last_chunk) {
    LogReaderList reader_list;
    LogTags tags;
    LogStatistics stats(false, true);
    SerializedLogBuffer log_buffer(&reader_list, &tags, &stats);

    log_buffer.SetSize(LOG_ID_MAIN, kLogBufferMinSize);
    log_buffer.Clear(LOG_ID_MAIN, 0);

    const uid_t kNonClearUid = 123;
    const std::string kDontClearMessage = "this message is not cleared";
    log_buffer.Log(LOG_ID_MAIN, log_time(0, 1), kNonClearUid, 1, 1, kDontClearMessage.data(),
                   kDontClearMessage.size());

    // Fill at least one chunk with a message with the UID that we'll clear
    const uid_t kClearUid = 555;
    const std::string kClearMessage(1024, 'c');
    size_t size_written = 0;
    while (size_written < kLogBufferMinSize / 2) {
        log_buffer.Log(LOG_ID_MAIN, log_time(1, size_written), kClearUid, 1, 1,
                       kClearMessage.data(), kClearMessage.size());
        size_written += kClearMessage.size();
    }

    log_buffer.Clear(LOG_ID_MAIN, kClearUid);

    // This previously would trigger a CHECK() in SerializedLogChunk::FinishWriting().
    log_buffer.Log(LOG_ID_MAIN, log_time(0, 2), kNonClearUid, 1, 1, kDontClearMessage.data(),
                   kDontClearMessage.size());
}

struct TestEntry {
    uint32_t uid;
    uint32_t pid;
    uint32_t tid;
    uint64_t sequence;
    log_time realtime;
    std::string msg;
};

SerializedLogChunk CreateChunk(size_t max_size, const std::vector<TestEntry>& entries,
                               bool finish_writing) {
    SerializedLogChunk chunk(max_size / SerializedLogBuffer::kChunkSizeDivisor);

    for (const auto& entry : entries) {
        if (!chunk.CanLog(sizeof(SerializedLogEntry) + entry.msg.size())) {
            EXPECT_TRUE(false) << "Test set up failure, entries don't fit in chunks";
            return chunk;
        }
        chunk.Log(entry.sequence, entry.realtime, entry.uid, entry.pid, entry.tid, entry.msg.data(),
                  entry.msg.size());
    }
    if (finish_writing) {
        chunk.FinishWriting();
    }
    return chunk;
}

void VerifyChunks(const std::list<SerializedLogChunk>& expected,
                  const std::list<SerializedLogChunk>& chunks) {
    int chunk = 0;
    auto expected_it = expected.begin();
    auto it = chunks.begin();
    for (; expected_it != expected.end() && it != chunks.end(); ++expected_it, ++it, ++chunk) {
        EXPECT_EQ(expected_it->reader_ref_count_, it->reader_ref_count_) << "chunk #" << chunk;
        EXPECT_EQ(expected_it->writer_active_, it->writer_active_) << "chunk #" << chunk;
        EXPECT_EQ(expected_it->highest_sequence_number_, it->highest_sequence_number_)
                << "chunk #" << chunk;
        EXPECT_EQ(expected_it->readers_, it->readers_) << "chunk #" << chunk;

        ASSERT_EQ(expected_it->contents_.size(), it->contents_.size()) << "chunk #" << chunk;
        ASSERT_EQ(expected_it->write_offset_, it->write_offset_) << "chunk #" << chunk;
        if (expected_it->contents_.size() > 0) {
            for (int i = 0; i < it->write_offset_; ++i) {
                EXPECT_EQ(expected_it->contents_.data()[i], it->contents_.data()[i])
                        << "chunk #" << chunk;
            }
        }

        ASSERT_EQ(expected_it->compressed_log_.size(), it->compressed_log_.size())
                << "chunk #" << chunk;
        if (expected_it->compressed_log_.size() > 0) {
            for (size_t i = 0; i < it->compressed_log_.size(); ++i) {
                EXPECT_EQ(expected_it->compressed_log_.data()[i], it->compressed_log_.data()[i])
                        << "chunk #" << chunk;
            }
        }
    }
    EXPECT_EQ(expected.end(), expected_it);
    EXPECT_EQ(chunks.end(), it);
}

// If no blocks are present before ClearLogsByUid() then no blocks should be output.
TEST(SerializedLogBuffer, uid_prune_no_blocks) {
    const uid_t kClearUid = 555;
    const size_t kMaxSize = kLogBufferMinSize;

    std::list<SerializedLogChunk> chunks;
    std::list<SerializedLogChunk> expected_chunks;

    ClearLogsByUid(chunks, kClearUid, kMaxSize, LOG_ID_MAIN, nullptr);
    VerifyChunks(expected_chunks, chunks);

    ClearLogsByUid(chunks, kClearUid, kMaxSize, LOG_ID_MAIN, nullptr);
    VerifyChunks(expected_chunks, chunks);
}

// If no UIDs to be cleared are found, then the _same exact_ block is returned.
TEST(SerializedLogBuffer, uid_prune_one_block_no_uid) {
    const uid_t kNonClearUid = 123;
    const uid_t kClearUid = 555;
    const size_t kMaxSize = kLogBufferMinSize;

    std::vector<TestEntry> entries = {
            {.uid = kNonClearUid,
             .pid = 10,
             .tid = 10,
             .sequence = 1,
             .realtime = log_time(0, 1),
             .msg = "some message"},
    };

    std::list<SerializedLogChunk> chunks;
    chunks.emplace_back(CreateChunk(kMaxSize, entries, false));
    void* original_chunk_address = reinterpret_cast<void*>(&chunks.front());

    std::list<SerializedLogChunk> expected_chunks;
    expected_chunks.push_back(CreateChunk(kMaxSize, entries, false));

    ClearLogsByUid(chunks, kClearUid, kMaxSize, LOG_ID_MAIN, nullptr);
    VerifyChunks(expected_chunks, chunks);
    void* after_clear_chunk_address = reinterpret_cast<void*>(&chunks.front());
    EXPECT_EQ(original_chunk_address, after_clear_chunk_address);

    ClearLogsByUid(chunks, kClearUid, kMaxSize, LOG_ID_MAIN, nullptr);
    VerifyChunks(expected_chunks, chunks);
    after_clear_chunk_address = reinterpret_cast<void*>(&chunks.front());
    EXPECT_EQ(original_chunk_address, after_clear_chunk_address);
}

std::vector<TestEntry> FilterEntries(const std::vector<TestEntry>& entries, uid_t uid_to_remove) {
    std::vector<TestEntry> filtered_entries;
    for (const auto& entry : entries) {
        if (entry.uid == uid_to_remove) {
            continue;
        }
        filtered_entries.emplace_back(entry);
    }
    return filtered_entries;
}

TEST(SerializedLogBuffer, uid_prune_one_block_some_uid) {
    const uid_t kNonClearUid = 123;
    const uid_t kClearUid = 555;
    const size_t kMaxSize = kLogBufferMinSize;

    std::list<SerializedLogChunk> chunks;
    std::vector<TestEntry> entries = {
            {.uid = kNonClearUid,
             .pid = 10,
             .tid = 10,
             .sequence = 1,
             .realtime = log_time(0, 1),
             .msg = "some message"},
            {.uid = kClearUid,
             .pid = 10,
             .tid = 10,
             .sequence = 2,
             .realtime = log_time(0, 1),
             .msg = "some cleared message"},
    };
    chunks.emplace_back(CreateChunk(kMaxSize, entries, false));

    std::list<SerializedLogChunk> expected_chunks;
    expected_chunks.emplace_back(CreateChunk(kMaxSize, FilterEntries(entries, kClearUid), false));

    ClearLogsByUid(chunks, kClearUid, kMaxSize, LOG_ID_MAIN, nullptr);
    VerifyChunks(expected_chunks, chunks);

    ClearLogsByUid(chunks, kClearUid, kMaxSize, LOG_ID_MAIN, nullptr);
    VerifyChunks(expected_chunks, chunks);
}

TEST(SerializedLogBuffer, uid_prune_one_block_all_uid) {
    const uid_t kClearUid = 555;
    const size_t kMaxSize = kLogBufferMinSize;

    std::list<SerializedLogChunk> chunks;
    std::vector<TestEntry> entries = {
            {.uid = kClearUid,
             .pid = 10,
             .tid = 10,
             .sequence = 1,
             .realtime = log_time(0, 1),
             .msg = "some message"},
            {.uid = kClearUid,
             .pid = 10,
             .tid = 10,
             .sequence = 2,
             .realtime = log_time(0, 1),
             .msg = "some cleared message"},
    };
    chunks.emplace_back(CreateChunk(kMaxSize, entries, false));

    std::list<SerializedLogChunk> expected_chunks;
    expected_chunks.emplace_back(CreateChunk(kMaxSize, {}, false));

    ClearLogsByUid(chunks, kClearUid, kMaxSize, LOG_ID_MAIN, nullptr);
    VerifyChunks(expected_chunks, chunks);

    ClearLogsByUid(chunks, kClearUid, kMaxSize, LOG_ID_MAIN, nullptr);
    VerifyChunks(expected_chunks, chunks);
}

TEST(SerializedLogBuffer, uid_prune_first_middle_last_chunks) {
    const uid_t kNonClearUid = 123;
    const uid_t kClearUid = 555;
    const std::string kMsg = "constant log message";
    const size_t kMaxSize =
            (sizeof(SerializedLogEntry) + kMsg.size()) * SerializedLogBuffer::kChunkSizeDivisor;

    std::list<SerializedLogChunk> chunks;
    std::vector<TestEntry> entries0 = {
            {.uid = kClearUid,
             .pid = 10,
             .tid = 10,
             .sequence = 1,
             .realtime = log_time(0, 1),
             .msg = kMsg},
    };
    chunks.emplace_back(CreateChunk(kMaxSize, entries0, true));
    std::vector<TestEntry> entries1 = {
            {.uid = kNonClearUid,
             .pid = 10,
             .tid = 10,
             .sequence = 2,
             .realtime = log_time(0, 1),
             .msg = kMsg},
    };
    chunks.emplace_back(CreateChunk(kMaxSize, entries1, true));
    std::vector<TestEntry> entries2 = {
            {.uid = kClearUid,
             .pid = 10,
             .tid = 10,
             .sequence = 3,
             .realtime = log_time(0, 1),
             .msg = kMsg},
    };
    chunks.emplace_back(CreateChunk(kMaxSize, entries2, true));
    std::vector<TestEntry> entries3 = {
            {.uid = kNonClearUid,
             .pid = 10,
             .tid = 10,
             .sequence = 4,
             .realtime = log_time(0, 1),
             .msg = kMsg},
    };
    chunks.emplace_back(CreateChunk(kMaxSize, entries3, true));
    std::vector<TestEntry> entries4 = {
            {.uid = kClearUid,
             .pid = 10,
             .tid = 10,
             .sequence = 5,
             .realtime = log_time(0, 1),
             .msg = kMsg},
    };
    chunks.emplace_back(CreateChunk(kMaxSize, entries4, false));

    std::list<SerializedLogChunk> expected_chunks;
    expected_chunks.emplace_back(CreateChunk(kMaxSize, entries1, true));
    expected_chunks.emplace_back(CreateChunk(kMaxSize, entries3, false));

    ClearLogsByUid(chunks, kClearUid, kMaxSize, LOG_ID_MAIN, nullptr);
    VerifyChunks(expected_chunks, chunks);

    ClearLogsByUid(chunks, kClearUid, kMaxSize, LOG_ID_MAIN, nullptr);
    VerifyChunks(expected_chunks, chunks);
}

TEST(SerializedLogBuffer, uid_prune_coalesce) {
    const uid_t kNonClearUid = 123;
    const uid_t kClearUid = 555;
    const std::string kMsg = "constant log message";
    const size_t kMaxSize =
            (sizeof(SerializedLogEntry) + kMsg.size()) * SerializedLogBuffer::kChunkSizeDivisor * 2;

    std::list<SerializedLogChunk> chunks;
    std::vector<TestEntry> entries0 = {
            {.uid = kNonClearUid,
             .pid = 10,
             .tid = 10,
             .sequence = 1,
             .realtime = log_time(0, 1),
             .msg = kMsg},
            {.uid = kNonClearUid,
             .pid = 10,
             .tid = 10,
             .sequence = 2,
             .realtime = log_time(0, 1),
             .msg = kMsg},
    };
    chunks.emplace_back(CreateChunk(kMaxSize, entries0, true));
    std::vector<TestEntry> entries1 = {
            {.uid = kNonClearUid,
             .pid = 10,
             .tid = 10,
             .sequence = 3,
             .realtime = log_time(0, 1),
             .msg = kMsg},
            {.uid = kClearUid,
             .pid = 10,
             .tid = 10,
             .sequence = 4,
             .realtime = log_time(0, 1),
             .msg = kMsg},
    };
    chunks.emplace_back(CreateChunk(kMaxSize, entries1, true));
    std::vector<TestEntry> entries2 = {
            {.uid = kClearUid,
             .pid = 10,
             .tid = 10,
             .sequence = 5,
             .realtime = log_time(0, 1),
             .msg = kMsg},
            {.uid = kClearUid,
             .pid = 10,
             .tid = 10,
             .sequence = 6,
             .realtime = log_time(0, 1),
             .msg = kMsg},
    };
    chunks.emplace_back(CreateChunk(kMaxSize, entries2, true));
    std::vector<TestEntry> entries3 = {
            {.uid = kNonClearUid,
             .pid = 10,
             .tid = 10,
             .sequence = 7,
             .realtime = log_time(0, 1),
             .msg = kMsg},
            {.uid = kNonClearUid,
             .pid = 10,
             .tid = 10,
             .sequence = 8,
             .realtime = log_time(0, 1),
             .msg = kMsg},
    };
    chunks.emplace_back(CreateChunk(kMaxSize, entries3, false));

    std::list<SerializedLogChunk> expected_chunks;
    expected_chunks.emplace_back(CreateChunk(kMaxSize, entries0, true));

    std::vector<TestEntry> expected_entries_1;
    expected_entries_1.emplace_back(entries1[0]);
    expected_entries_1.emplace_back(entries3[0]);
    expected_chunks.emplace_back(CreateChunk(kMaxSize, expected_entries_1, true));

    std::vector<TestEntry> expected_entries_2;
    expected_entries_2.emplace_back(entries3[1]);
    expected_chunks.emplace_back(CreateChunk(kMaxSize, expected_entries_2, false));

    ClearLogsByUid(chunks, kClearUid, kMaxSize, LOG_ID_MAIN, nullptr);
    VerifyChunks(expected_chunks, chunks);

    ClearLogsByUid(chunks, kClearUid, kMaxSize, LOG_ID_MAIN, nullptr);
    VerifyChunks(expected_chunks, chunks);
}