1 /*
2 * Copyright (C) 2021 The Android Open Source Project
3 *
4 * Licensed under the Apache License, Version 2.0 (the "License");
5 * you may not use this file except in compliance with the License.
6 * You may obtain a copy of the License at
7 *
8 * http://www.apache.org/licenses/LICENSE-2.0
9 *
10 * Unless required by applicable law or agreed to in writing, software
11 * distributed under the License is distributed on an "AS IS" BASIS,
12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13 * See the License for the specific language governing permissions and
14 * limitations under the License.
15 */
16
17 #include "SerializedLogBuffer.h"
18
19 #include <gtest/gtest.h>
20 #include <log/log.h>
21
22 #include "LogReaderList.h"
23 #include "LogSize.h"
24 #include "LogStatistics.h"
25 #include "LogTags.h"
26 #include "SerializedLogChunk.h"
27 #include "SerializedLogEntry.h"
28
29 // b/188858988 - Previously, if clearing UID logs erased the back-most chunk, then a chunk that has
30 // previously been closed for writing will be the back-most chunk in the list. Subsequent calls to
31 // SerializedLogBuffer::Log() will call SerializedLogChunk::FinishWriting(), which triggered a
32 // CHECK().
TEST(SerializedLogBuffer,uid_prune_deletes_last_chunk)33 TEST(SerializedLogBuffer, uid_prune_deletes_last_chunk) {
34 LogReaderList reader_list;
35 LogTags tags;
36 LogStatistics stats(false, true);
37 SerializedLogBuffer log_buffer(&reader_list, &tags, &stats);
38
39 log_buffer.SetSize(LOG_ID_MAIN, kLogBufferMinSize);
40 log_buffer.Clear(LOG_ID_MAIN, 0);
41
42 const uid_t kNonClearUid = 123;
43 const std::string kDontClearMessage = "this message is not cleared";
44 log_buffer.Log(LOG_ID_MAIN, log_time(0, 1), kNonClearUid, 1, 1, kDontClearMessage.data(),
45 kDontClearMessage.size());
46
47 // Fill at least one chunk with a message with the UID that we'll clear
48 const uid_t kClearUid = 555;
49 const std::string kClearMessage(1024, 'c');
50 size_t size_written = 0;
51 while (size_written < kLogBufferMinSize / 2) {
52 log_buffer.Log(LOG_ID_MAIN, log_time(1, size_written), kClearUid, 1, 1,
53 kClearMessage.data(), kClearMessage.size());
54 size_written += kClearMessage.size();
55 }
56
57 log_buffer.Clear(LOG_ID_MAIN, kClearUid);
58
59 // This previously would trigger a CHECK() in SerializedLogChunk::FinishWriting().
60 log_buffer.Log(LOG_ID_MAIN, log_time(0, 2), kNonClearUid, 1, 1, kDontClearMessage.data(),
61 kDontClearMessage.size());
62 }
63
64 struct TestEntry {
65 uint32_t uid;
66 uint32_t pid;
67 uint32_t tid;
68 uint64_t sequence;
69 log_time realtime;
70 std::string msg;
71 };
72
CreateChunk(size_t max_size,const std::vector<TestEntry> & entries,bool finish_writing)73 SerializedLogChunk CreateChunk(size_t max_size, const std::vector<TestEntry>& entries,
74 bool finish_writing) {
75 SerializedLogChunk chunk(max_size / SerializedLogBuffer::kChunkSizeDivisor);
76
77 for (const auto& entry : entries) {
78 if (!chunk.CanLog(sizeof(SerializedLogEntry) + entry.msg.size())) {
79 EXPECT_TRUE(false) << "Test set up failure, entries don't fit in chunks";
80 return chunk;
81 }
82 chunk.Log(entry.sequence, entry.realtime, entry.uid, entry.pid, entry.tid, entry.msg.data(),
83 entry.msg.size());
84 }
85 if (finish_writing) {
86 chunk.FinishWriting();
87 }
88 return chunk;
89 }
90
VerifyChunks(const std::list<SerializedLogChunk> & expected,const std::list<SerializedLogChunk> & chunks)91 void VerifyChunks(const std::list<SerializedLogChunk>& expected,
92 const std::list<SerializedLogChunk>& chunks) {
93 int chunk = 0;
94 auto expected_it = expected.begin();
95 auto it = chunks.begin();
96 for (; expected_it != expected.end() && it != chunks.end(); ++expected_it, ++it, ++chunk) {
97 EXPECT_EQ(expected_it->reader_ref_count_, it->reader_ref_count_) << "chunk #" << chunk;
98 EXPECT_EQ(expected_it->writer_active_, it->writer_active_) << "chunk #" << chunk;
99 EXPECT_EQ(expected_it->highest_sequence_number_, it->highest_sequence_number_)
100 << "chunk #" << chunk;
101 EXPECT_EQ(expected_it->readers_, it->readers_) << "chunk #" << chunk;
102
103 ASSERT_EQ(expected_it->contents_.size(), it->contents_.size()) << "chunk #" << chunk;
104 ASSERT_EQ(expected_it->write_offset_, it->write_offset_) << "chunk #" << chunk;
105 if (expected_it->contents_.size() > 0) {
106 for (int i = 0; i < it->write_offset_; ++i) {
107 EXPECT_EQ(expected_it->contents_.data()[i], it->contents_.data()[i])
108 << "chunk #" << chunk;
109 }
110 }
111
112 ASSERT_EQ(expected_it->compressed_log_.size(), it->compressed_log_.size())
113 << "chunk #" << chunk;
114 if (expected_it->compressed_log_.size() > 0) {
115 for (size_t i = 0; i < it->compressed_log_.size(); ++i) {
116 EXPECT_EQ(expected_it->compressed_log_.data()[i], it->compressed_log_.data()[i])
117 << "chunk #" << chunk;
118 }
119 }
120 }
121 EXPECT_EQ(expected.end(), expected_it);
122 EXPECT_EQ(chunks.end(), it);
123 }
124
125 // If no blocks are present before ClearLogsByUid() then no blocks should be output.
TEST(SerializedLogBuffer,uid_prune_no_blocks)126 TEST(SerializedLogBuffer, uid_prune_no_blocks) {
127 const uid_t kClearUid = 555;
128 const size_t kMaxSize = kLogBufferMinSize;
129
130 std::list<SerializedLogChunk> chunks;
131 std::list<SerializedLogChunk> expected_chunks;
132
133 ClearLogsByUid(chunks, kClearUid, kMaxSize, LOG_ID_MAIN, nullptr);
134 VerifyChunks(expected_chunks, chunks);
135
136 ClearLogsByUid(chunks, kClearUid, kMaxSize, LOG_ID_MAIN, nullptr);
137 VerifyChunks(expected_chunks, chunks);
138 }
139
140 // If no UIDs to be cleared are found, then the _same exact_ block is returned.
TEST(SerializedLogBuffer,uid_prune_one_block_no_uid)141 TEST(SerializedLogBuffer, uid_prune_one_block_no_uid) {
142 const uid_t kNonClearUid = 123;
143 const uid_t kClearUid = 555;
144 const size_t kMaxSize = kLogBufferMinSize;
145
146 std::vector<TestEntry> entries = {
147 {.uid = kNonClearUid,
148 .pid = 10,
149 .tid = 10,
150 .sequence = 1,
151 .realtime = log_time(0, 1),
152 .msg = "some message"},
153 };
154
155 std::list<SerializedLogChunk> chunks;
156 chunks.emplace_back(CreateChunk(kMaxSize, entries, false));
157 void* original_chunk_address = reinterpret_cast<void*>(&chunks.front());
158
159 std::list<SerializedLogChunk> expected_chunks;
160 expected_chunks.push_back(CreateChunk(kMaxSize, entries, false));
161
162 ClearLogsByUid(chunks, kClearUid, kMaxSize, LOG_ID_MAIN, nullptr);
163 VerifyChunks(expected_chunks, chunks);
164 void* after_clear_chunk_address = reinterpret_cast<void*>(&chunks.front());
165 EXPECT_EQ(original_chunk_address, after_clear_chunk_address);
166
167 ClearLogsByUid(chunks, kClearUid, kMaxSize, LOG_ID_MAIN, nullptr);
168 VerifyChunks(expected_chunks, chunks);
169 after_clear_chunk_address = reinterpret_cast<void*>(&chunks.front());
170 EXPECT_EQ(original_chunk_address, after_clear_chunk_address);
171 }
172
FilterEntries(const std::vector<TestEntry> & entries,uid_t uid_to_remove)173 std::vector<TestEntry> FilterEntries(const std::vector<TestEntry>& entries, uid_t uid_to_remove) {
174 std::vector<TestEntry> filtered_entries;
175 for (const auto& entry : entries) {
176 if (entry.uid == uid_to_remove) {
177 continue;
178 }
179 filtered_entries.emplace_back(entry);
180 }
181 return filtered_entries;
182 }
183
TEST(SerializedLogBuffer,uid_prune_one_block_some_uid)184 TEST(SerializedLogBuffer, uid_prune_one_block_some_uid) {
185 const uid_t kNonClearUid = 123;
186 const uid_t kClearUid = 555;
187 const size_t kMaxSize = kLogBufferMinSize;
188
189 std::list<SerializedLogChunk> chunks;
190 std::vector<TestEntry> entries = {
191 {.uid = kNonClearUid,
192 .pid = 10,
193 .tid = 10,
194 .sequence = 1,
195 .realtime = log_time(0, 1),
196 .msg = "some message"},
197 {.uid = kClearUid,
198 .pid = 10,
199 .tid = 10,
200 .sequence = 2,
201 .realtime = log_time(0, 1),
202 .msg = "some cleared message"},
203 };
204 chunks.emplace_back(CreateChunk(kMaxSize, entries, false));
205
206 std::list<SerializedLogChunk> expected_chunks;
207 expected_chunks.emplace_back(CreateChunk(kMaxSize, FilterEntries(entries, kClearUid), false));
208
209 ClearLogsByUid(chunks, kClearUid, kMaxSize, LOG_ID_MAIN, nullptr);
210 VerifyChunks(expected_chunks, chunks);
211
212 ClearLogsByUid(chunks, kClearUid, kMaxSize, LOG_ID_MAIN, nullptr);
213 VerifyChunks(expected_chunks, chunks);
214 }
215
TEST(SerializedLogBuffer,uid_prune_one_block_all_uid)216 TEST(SerializedLogBuffer, uid_prune_one_block_all_uid) {
217 const uid_t kClearUid = 555;
218 const size_t kMaxSize = kLogBufferMinSize;
219
220 std::list<SerializedLogChunk> chunks;
221 std::vector<TestEntry> entries = {
222 {.uid = kClearUid,
223 .pid = 10,
224 .tid = 10,
225 .sequence = 1,
226 .realtime = log_time(0, 1),
227 .msg = "some message"},
228 {.uid = kClearUid,
229 .pid = 10,
230 .tid = 10,
231 .sequence = 2,
232 .realtime = log_time(0, 1),
233 .msg = "some cleared message"},
234 };
235 chunks.emplace_back(CreateChunk(kMaxSize, entries, false));
236
237 std::list<SerializedLogChunk> expected_chunks;
238 expected_chunks.emplace_back(CreateChunk(kMaxSize, {}, false));
239
240 ClearLogsByUid(chunks, kClearUid, kMaxSize, LOG_ID_MAIN, nullptr);
241 VerifyChunks(expected_chunks, chunks);
242
243 ClearLogsByUid(chunks, kClearUid, kMaxSize, LOG_ID_MAIN, nullptr);
244 VerifyChunks(expected_chunks, chunks);
245 }
246
TEST(SerializedLogBuffer,uid_prune_first_middle_last_chunks)247 TEST(SerializedLogBuffer, uid_prune_first_middle_last_chunks) {
248 const uid_t kNonClearUid = 123;
249 const uid_t kClearUid = 555;
250 const std::string kMsg = "constant log message";
251 const size_t kMaxSize =
252 (sizeof(SerializedLogEntry) + kMsg.size()) * SerializedLogBuffer::kChunkSizeDivisor;
253
254 std::list<SerializedLogChunk> chunks;
255 std::vector<TestEntry> entries0 = {
256 {.uid = kClearUid,
257 .pid = 10,
258 .tid = 10,
259 .sequence = 1,
260 .realtime = log_time(0, 1),
261 .msg = kMsg},
262 };
263 chunks.emplace_back(CreateChunk(kMaxSize, entries0, true));
264 std::vector<TestEntry> entries1 = {
265 {.uid = kNonClearUid,
266 .pid = 10,
267 .tid = 10,
268 .sequence = 2,
269 .realtime = log_time(0, 1),
270 .msg = kMsg},
271 };
272 chunks.emplace_back(CreateChunk(kMaxSize, entries1, true));
273 std::vector<TestEntry> entries2 = {
274 {.uid = kClearUid,
275 .pid = 10,
276 .tid = 10,
277 .sequence = 3,
278 .realtime = log_time(0, 1),
279 .msg = kMsg},
280 };
281 chunks.emplace_back(CreateChunk(kMaxSize, entries2, true));
282 std::vector<TestEntry> entries3 = {
283 {.uid = kNonClearUid,
284 .pid = 10,
285 .tid = 10,
286 .sequence = 4,
287 .realtime = log_time(0, 1),
288 .msg = kMsg},
289 };
290 chunks.emplace_back(CreateChunk(kMaxSize, entries3, true));
291 std::vector<TestEntry> entries4 = {
292 {.uid = kClearUid,
293 .pid = 10,
294 .tid = 10,
295 .sequence = 5,
296 .realtime = log_time(0, 1),
297 .msg = kMsg},
298 };
299 chunks.emplace_back(CreateChunk(kMaxSize, entries4, false));
300
301 std::list<SerializedLogChunk> expected_chunks;
302 expected_chunks.emplace_back(CreateChunk(kMaxSize, entries1, true));
303 expected_chunks.emplace_back(CreateChunk(kMaxSize, entries3, false));
304
305 ClearLogsByUid(chunks, kClearUid, kMaxSize, LOG_ID_MAIN, nullptr);
306 VerifyChunks(expected_chunks, chunks);
307
308 ClearLogsByUid(chunks, kClearUid, kMaxSize, LOG_ID_MAIN, nullptr);
309 VerifyChunks(expected_chunks, chunks);
310 }
311
TEST(SerializedLogBuffer,uid_prune_coalesce)312 TEST(SerializedLogBuffer, uid_prune_coalesce) {
313 const uid_t kNonClearUid = 123;
314 const uid_t kClearUid = 555;
315 const std::string kMsg = "constant log message";
316 const size_t kMaxSize =
317 (sizeof(SerializedLogEntry) + kMsg.size()) * SerializedLogBuffer::kChunkSizeDivisor * 2;
318
319 std::list<SerializedLogChunk> chunks;
320 std::vector<TestEntry> entries0 = {
321 {.uid = kNonClearUid,
322 .pid = 10,
323 .tid = 10,
324 .sequence = 1,
325 .realtime = log_time(0, 1),
326 .msg = kMsg},
327 {.uid = kNonClearUid,
328 .pid = 10,
329 .tid = 10,
330 .sequence = 2,
331 .realtime = log_time(0, 1),
332 .msg = kMsg},
333 };
334 chunks.emplace_back(CreateChunk(kMaxSize, entries0, true));
335 std::vector<TestEntry> entries1 = {
336 {.uid = kNonClearUid,
337 .pid = 10,
338 .tid = 10,
339 .sequence = 3,
340 .realtime = log_time(0, 1),
341 .msg = kMsg},
342 {.uid = kClearUid,
343 .pid = 10,
344 .tid = 10,
345 .sequence = 4,
346 .realtime = log_time(0, 1),
347 .msg = kMsg},
348 };
349 chunks.emplace_back(CreateChunk(kMaxSize, entries1, true));
350 std::vector<TestEntry> entries2 = {
351 {.uid = kClearUid,
352 .pid = 10,
353 .tid = 10,
354 .sequence = 5,
355 .realtime = log_time(0, 1),
356 .msg = kMsg},
357 {.uid = kClearUid,
358 .pid = 10,
359 .tid = 10,
360 .sequence = 6,
361 .realtime = log_time(0, 1),
362 .msg = kMsg},
363 };
364 chunks.emplace_back(CreateChunk(kMaxSize, entries2, true));
365 std::vector<TestEntry> entries3 = {
366 {.uid = kNonClearUid,
367 .pid = 10,
368 .tid = 10,
369 .sequence = 7,
370 .realtime = log_time(0, 1),
371 .msg = kMsg},
372 {.uid = kNonClearUid,
373 .pid = 10,
374 .tid = 10,
375 .sequence = 8,
376 .realtime = log_time(0, 1),
377 .msg = kMsg},
378 };
379 chunks.emplace_back(CreateChunk(kMaxSize, entries3, false));
380
381 std::list<SerializedLogChunk> expected_chunks;
382 expected_chunks.emplace_back(CreateChunk(kMaxSize, entries0, true));
383
384 std::vector<TestEntry> expected_entries_1;
385 expected_entries_1.emplace_back(entries1[0]);
386 expected_entries_1.emplace_back(entries3[0]);
387 expected_chunks.emplace_back(CreateChunk(kMaxSize, expected_entries_1, true));
388
389 std::vector<TestEntry> expected_entries_2;
390 expected_entries_2.emplace_back(entries3[1]);
391 expected_chunks.emplace_back(CreateChunk(kMaxSize, expected_entries_2, false));
392
393 ClearLogsByUid(chunks, kClearUid, kMaxSize, LOG_ID_MAIN, nullptr);
394 VerifyChunks(expected_chunks, chunks);
395
396 ClearLogsByUid(chunks, kClearUid, kMaxSize, LOG_ID_MAIN, nullptr);
397 VerifyChunks(expected_chunks, chunks);
398 }
399