blob: dbbe2f2b0df3388dc8c963a453ee0462dc45fd28 [file] [log] [blame]
/*
* 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);
}