logging/logd/SerializedFlushToStateTest.cpp

/*
 * Copyright (C) 2020 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 "SerializedFlushToState.h"

#include <map>

#include <android-base/logging.h>
#include <android-base/stringprintf.h>
#include <android-base/strings.h>
#include <gtest/gtest.h>

using android::base::Join;
using android::base::StringPrintf;

constexpr size_t kChunkSize = 3 * 4096;

class SerializedFlushToStateTest : public testing::Test {
  protected:
    void SetUp() override {
        // This test spams many unneeded INFO logs, so we suppress them.
        old_log_severity_ = android::base::SetMinimumLogSeverity(android::base::WARNING);
    }
    void TearDown() override { android::base::SetMinimumLogSeverity(old_log_severity_); }

    std::string TestReport(const std::vector<uint64_t>& expected, const std::vector<uint64_t>& read)
            REQUIRES(logd_lock) {
        auto sequence_to_log_id = [&](uint64_t sequence) -> int {
            for (const auto& [log_id, sequences] : sequence_numbers_per_buffer_) {
                if (std::find(sequences.begin(), sequences.end(), sequence) != sequences.end()) {
                    return log_id;
                }
            }
            return -1;
        };

        std::map<int, std::vector<uint64_t>> missing_sequences;
        std::vector<uint64_t> missing_expected;
        std::set_difference(expected.begin(), expected.end(), read.begin(), read.end(),
                            std::back_inserter(missing_expected));
        for (uint64_t sequence : missing_expected) {
            int log_id = sequence_to_log_id(sequence);
            missing_sequences[log_id].emplace_back(sequence);
        }

        std::map<int, std::vector<uint64_t>> extra_sequences;
        std::vector<uint64_t> extra_read;
        std::set_difference(read.begin(), read.end(), expected.begin(), expected.end(),
                            std::back_inserter(extra_read));
        for (uint64_t sequence : extra_read) {
            int log_id = sequence_to_log_id(sequence);
            extra_sequences[log_id].emplace_back(sequence);
        }

        std::vector<std::string> errors;
        for (const auto& [log_id, sequences] : missing_sequences) {
            errors.emplace_back(
                    StringPrintf("Log id %d missing %zu sequences", log_id, sequences.size()));
        }

        for (const auto& [log_id, sequences] : extra_sequences) {
            errors.emplace_back(
                    StringPrintf("Log id %d has extra %zu sequences", log_id, sequences.size()));
        }

        return Join(errors, ", ");
    }

    // Read sequence numbers in order from SerializedFlushToState for every mask combination and all
    // sequence numbers from 0 through the highest logged sequence number + 1.
    // This assumes that all of the logs have already been written.
    void TestAllReading() REQUIRES(logd_lock) {
        uint64_t max_sequence = sequence_ + 1;
        uint32_t max_mask = (1 << LOG_ID_MAX) - 1;
        for (uint64_t sequence = 0; sequence < max_sequence; ++sequence) {
            for (uint32_t mask = 0; mask < max_mask; ++mask) {
                auto state = SerializedFlushToState{sequence, mask, log_chunks_};
                TestReading(sequence, mask, state);
            }
        }
    }

    // Similar to TestAllReading() except that it doesn't assume any logs are in the buffer, instead
    // it calls write_logs() in a loop for sequence/mask combination.  It clears log_chunks_ and
    // sequence_numbers_per_buffer_ between calls, such that only the sequence numbers written in
    // the previous call to write_logs() are expected.
    void TestAllReadingWithFutureMessages(const std::function<bool(int)>& write_logs)
            REQUIRES(logd_lock) {
        uint64_t max_sequence = sequence_ + 1;
        uint32_t max_mask = (1 << LOG_ID_MAX) - 1;
        for (uint64_t sequence = 1; sequence < max_sequence; ++sequence) {
            for (uint32_t mask = 1; mask < max_mask; ++mask) {
                log_id_for_each(i) { log_chunks_[i].clear(); }
                auto state = SerializedFlushToState{sequence, mask, log_chunks_};
                int loop_count = 0;
                while (write_logs(loop_count++)) {
                    TestReading(sequence, mask, state);
                    sequence_numbers_per_buffer_.clear();
                }
            }
        }
    }

    void TestReading(uint64_t start, LogMask log_mask, SerializedFlushToState& state)
            REQUIRES(logd_lock) {
        std::vector<uint64_t> expected_sequence;
        log_id_for_each(i) {
            if (((1 << i) & log_mask) == 0) {
                continue;
            }
            for (const auto& sequence : sequence_numbers_per_buffer_[i]) {
                if (sequence >= start) {
                    expected_sequence.emplace_back(sequence);
                }
            }
        }
        std::sort(expected_sequence.begin(), expected_sequence.end());

        std::vector<uint64_t> read_sequence;

        while (state.HasUnreadLogs()) {
            auto top = state.PopNextUnreadLog();
            read_sequence.emplace_back(top.entry->sequence());
        }

        EXPECT_TRUE(std::is_sorted(read_sequence.begin(), read_sequence.end()));

        EXPECT_EQ(expected_sequence.size(), read_sequence.size());

        EXPECT_EQ(expected_sequence, read_sequence)
                << "start: " << start << " log_mask: " << log_mask << " "
                << TestReport(expected_sequence, read_sequence);
    }

    // Add a chunk with the given messages to the a given log buffer.  Keep track of the sequence
    // numbers for future validation.  Optionally mark the block as having finished writing.
    void AddChunkWithMessages(bool finish_writing, int buffer,
                              const std::vector<std::string>& messages) REQUIRES(logd_lock) {
        auto chunk = SerializedLogChunk{kChunkSize};
        for (const auto& message : messages) {
            auto sequence = sequence_++;
            sequence_numbers_per_buffer_[buffer].emplace_back(sequence);
            ASSERT_TRUE(chunk.CanLog(message.size() + 1));
            chunk.Log(sequence, log_time(), 0, 1, 1, message.c_str(), message.size() + 1);
        }
        if (finish_writing) {
            chunk.FinishWriting();
        }
        log_chunks_[buffer].emplace_back(std::move(chunk));
    }

    android::base::LogSeverity old_log_severity_;
    std::map<int, std::vector<uint64_t>> sequence_numbers_per_buffer_;
    std::list<SerializedLogChunk> log_chunks_[LOG_ID_MAX];
    uint64_t sequence_ = 1;
};

// 0: multiple chunks, with variable number of entries, with/without finishing writing
// 1: 1 chunk with 1 log and finished writing
// 2: 1 chunk with 1 log and not finished writing
// 3: 1 chunk with 0 logs and not finished writing
// 4: 1 chunk with 0 logs and finished writing (impossible, but SerializedFlushToState handles it)
// 5-7: 0 chunks
TEST_F(SerializedFlushToStateTest, smoke) {
    auto lock = std::lock_guard{logd_lock};
    AddChunkWithMessages(true, 0, {"1st", "2nd"});
    AddChunkWithMessages(true, 1, {"3rd"});
    AddChunkWithMessages(false, 0, {"4th"});
    AddChunkWithMessages(true, 0, {"4th", "5th", "more", "even", "more", "go", "here"});
    AddChunkWithMessages(false, 2, {"6th"});
    AddChunkWithMessages(true, 0, {"7th"});
    AddChunkWithMessages(false, 3, {});
    AddChunkWithMessages(true, 4, {});

    TestAllReading();
}

TEST_F(SerializedFlushToStateTest, random) {
    auto lock = std::lock_guard{logd_lock};
    srand(1);
    for (int count = 0; count < 20; ++count) {
        unsigned int num_messages = 1 + rand() % 15;
        auto messages = std::vector<std::string>{num_messages, "same message"};

        bool compress = rand() % 2;
        int buf = rand() % LOG_ID_MAX;

        AddChunkWithMessages(compress, buf, messages);
    }

    TestAllReading();
}

// Same start as smoke, but we selectively write logs to the buffers and ensure they're read.
TEST_F(SerializedFlushToStateTest, future_writes) {
    auto lock = std::lock_guard{logd_lock};
    auto write_logs = [&](int loop_count) REQUIRES(logd_lock) {
        switch (loop_count) {
            case 0:
                // Initial writes.
                AddChunkWithMessages(true, 0, {"1st", "2nd"});
                AddChunkWithMessages(true, 1, {"3rd"});
                AddChunkWithMessages(false, 0, {"4th"});
                AddChunkWithMessages(true, 0, {"4th", "5th", "more", "even", "more", "go", "here"});
                AddChunkWithMessages(false, 2, {"6th"});
                AddChunkWithMessages(true, 0, {"7th"});
                AddChunkWithMessages(false, 3, {});
                AddChunkWithMessages(true, 4, {});
                break;
            case 1:
                // Smoke test, add a simple chunk.
                AddChunkWithMessages(true, 0, {"1st", "2nd"});
                break;
            case 2:
                // Add chunks to all but one of the logs.
                AddChunkWithMessages(true, 0, {"1st", "2nd"});
                AddChunkWithMessages(true, 1, {"1st", "2nd"});
                AddChunkWithMessages(true, 2, {"1st", "2nd"});
                AddChunkWithMessages(true, 3, {"1st", "2nd"});
                AddChunkWithMessages(true, 4, {"1st", "2nd"});
                AddChunkWithMessages(true, 5, {"1st", "2nd"});
                AddChunkWithMessages(true, 6, {"1st", "2nd"});
                break;
            case 3:
                // Finally add chunks to all logs.
                AddChunkWithMessages(true, 0, {"1st", "2nd"});
                AddChunkWithMessages(true, 1, {"1st", "2nd"});
                AddChunkWithMessages(true, 2, {"1st", "2nd"});
                AddChunkWithMessages(true, 3, {"1st", "2nd"});
                AddChunkWithMessages(true, 4, {"1st", "2nd"});
                AddChunkWithMessages(true, 5, {"1st", "2nd"});
                AddChunkWithMessages(true, 6, {"1st", "2nd"});
                AddChunkWithMessages(true, 7, {"1st", "2nd"});
                break;
            default:
                return false;
        }
        return true;
    };

    TestAllReadingWithFutureMessages(write_logs);
}

TEST_F(SerializedFlushToStateTest, no_dangling_references) {
    auto lock = std::lock_guard{logd_lock};
    AddChunkWithMessages(true, 0, {"1st", "2nd"});
    AddChunkWithMessages(true, 0, {"3rd", "4th"});

    auto state = SerializedFlushToState{1, kLogMaskAll, log_chunks_};

    ASSERT_EQ(log_chunks_[0].size(), 2U);
    auto first_chunk = log_chunks_[0].begin();
    auto second_chunk = std::next(first_chunk);

    ASSERT_TRUE(state.HasUnreadLogs());
    auto first_log = state.PopNextUnreadLog();
    EXPECT_STREQ(first_log.entry->msg(), "1st");
    EXPECT_EQ(first_chunk->reader_ref_count(), 1U);
    EXPECT_EQ(second_chunk->reader_ref_count(), 0U);

    ASSERT_TRUE(state.HasUnreadLogs());
    auto second_log = state.PopNextUnreadLog();
    EXPECT_STREQ(second_log.entry->msg(), "2nd");
    EXPECT_EQ(first_chunk->reader_ref_count(), 1U);
    EXPECT_EQ(second_chunk->reader_ref_count(), 0U);

    ASSERT_TRUE(state.HasUnreadLogs());
    auto third_log = state.PopNextUnreadLog();
    EXPECT_STREQ(third_log.entry->msg(), "3rd");
    EXPECT_EQ(first_chunk->reader_ref_count(), 0U);
    EXPECT_EQ(second_chunk->reader_ref_count(), 1U);

    ASSERT_TRUE(state.HasUnreadLogs());
    auto fourth_log = state.PopNextUnreadLog();
    EXPECT_STREQ(fourth_log.entry->msg(), "4th");
    EXPECT_EQ(first_chunk->reader_ref_count(), 0U);
    EXPECT_EQ(second_chunk->reader_ref_count(), 1U);

    EXPECT_FALSE(state.HasUnreadLogs());
}

TEST(SerializedFlushToState, Prune) {
    auto lock = std::lock_guard{logd_lock};
    auto chunk = SerializedLogChunk{kChunkSize};
    chunk.Log(1, log_time(), 0, 1, 1, "abc", 3);
    chunk.Log(2, log_time(), 0, 1, 1, "abc", 3);
    chunk.Log(3, log_time(), 0, 1, 1, "abc", 3);
    chunk.FinishWriting();

    std::list<SerializedLogChunk> log_chunks[LOG_ID_MAX];
    log_chunks[LOG_ID_MAIN].emplace_back(std::move(chunk));

    auto state = SerializedFlushToState{1, kLogMaskAll, log_chunks};
    ASSERT_TRUE(state.HasUnreadLogs());

    state.Prune(LOG_ID_MAIN);
}