1 /*
2 * Copyright (C) 2020 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 "LogBufferTest.h"
18
19 class ChattyLogBufferTest : public LogBufferTest {};
20
TEST_P(ChattyLogBufferTest,deduplication_simple)21 TEST_P(ChattyLogBufferTest, deduplication_simple) {
22 auto make_message = [&](uint32_t sec, const char* tag, const char* msg,
23 bool regex = false) -> LogMessage {
24 logger_entry entry = {
25 .pid = 1, .tid = 1, .sec = sec, .nsec = 1, .lid = LOG_ID_MAIN, .uid = 0};
26 std::string message;
27 message.push_back(ANDROID_LOG_INFO);
28 message.append(tag);
29 message.push_back('\0');
30 message.append(msg);
31 message.push_back('\0');
32 return {entry, message, regex};
33 };
34
35 // clang-format off
36 std::vector<LogMessage> log_messages = {
37 make_message(0, "test_tag", "duplicate"),
38 make_message(1, "test_tag", "duplicate"),
39 make_message(2, "test_tag", "not_same"),
40 make_message(3, "test_tag", "duplicate"),
41 make_message(4, "test_tag", "duplicate"),
42 make_message(5, "test_tag", "not_same"),
43 make_message(6, "test_tag", "duplicate"),
44 make_message(7, "test_tag", "duplicate"),
45 make_message(8, "test_tag", "duplicate"),
46 make_message(9, "test_tag", "not_same"),
47 make_message(10, "test_tag", "duplicate"),
48 make_message(11, "test_tag", "duplicate"),
49 make_message(12, "test_tag", "duplicate"),
50 make_message(13, "test_tag", "duplicate"),
51 make_message(14, "test_tag", "duplicate"),
52 make_message(15, "test_tag", "duplicate"),
53 make_message(16, "test_tag", "not_same"),
54 make_message(100, "test_tag", "duplicate"),
55 make_message(200, "test_tag", "duplicate"),
56 make_message(300, "test_tag", "duplicate"),
57 };
58 // clang-format on
59 FixupMessages(&log_messages);
60 LogMessages(log_messages);
61
62 std::vector<LogMessage> expected_log_messages = {
63 make_message(0, "test_tag", "duplicate"),
64 make_message(1, "test_tag", "duplicate"),
65 make_message(2, "test_tag", "not_same"),
66 make_message(3, "test_tag", "duplicate"),
67 make_message(4, "test_tag", "duplicate"),
68 make_message(5, "test_tag", "not_same"),
69 // 3 duplicate logs together print the first, a 1 count chatty message, then the last.
70 make_message(6, "test_tag", "duplicate"),
71 make_message(7, "chatty", "uid=0\\([^\\)]+\\) [^ ]+ identical 1 line", true),
72 make_message(8, "test_tag", "duplicate"),
73 make_message(9, "test_tag", "not_same"),
74 // 6 duplicate logs together print the first, a 4 count chatty message, then the last.
75 make_message(10, "test_tag", "duplicate"),
76 make_message(14, "chatty", "uid=0\\([^\\)]+\\) [^ ]+ identical 4 lines", true),
77 make_message(15, "test_tag", "duplicate"),
78 make_message(16, "test_tag", "not_same"),
79 // duplicate logs > 1 minute apart are not deduplicated.
80 make_message(100, "test_tag", "duplicate"),
81 make_message(200, "test_tag", "duplicate"),
82 make_message(300, "test_tag", "duplicate"),
83 };
84 FixupMessages(&expected_log_messages);
85 auto flush_result = FlushMessages();
86 CompareLogMessages(expected_log_messages, flush_result.messages);
87 };
88
TEST_P(ChattyLogBufferTest,deduplication_overflow)89 TEST_P(ChattyLogBufferTest, deduplication_overflow) {
90 auto make_message = [&](uint32_t sec, const char* tag, const char* msg,
91 bool regex = false) -> LogMessage {
92 logger_entry entry = {
93 .pid = 1, .tid = 1, .sec = sec, .nsec = 1, .lid = LOG_ID_MAIN, .uid = 0};
94 std::string message;
95 message.push_back(ANDROID_LOG_INFO);
96 message.append(tag);
97 message.push_back('\0');
98 message.append(msg);
99 message.push_back('\0');
100 return {entry, message, regex};
101 };
102
103 uint32_t sec = 0;
104 std::vector<LogMessage> log_messages = {
105 make_message(sec++, "test_tag", "normal"),
106 };
107 size_t expired_per_chatty_message = std::numeric_limits<uint16_t>::max();
108 for (size_t i = 0; i < expired_per_chatty_message + 3; ++i) {
109 log_messages.emplace_back(make_message(sec++, "test_tag", "duplicate"));
110 }
111 log_messages.emplace_back(make_message(sec++, "test_tag", "normal"));
112 FixupMessages(&log_messages);
113 LogMessages(log_messages);
114
115 std::vector<LogMessage> expected_log_messages = {
116 make_message(0, "test_tag", "normal"),
117 make_message(1, "test_tag", "duplicate"),
118 make_message(expired_per_chatty_message + 1, "chatty",
119 "uid=0\\([^\\)]+\\) [^ ]+ identical 65535 lines", true),
120 make_message(expired_per_chatty_message + 2, "chatty",
121 "uid=0\\([^\\)]+\\) [^ ]+ identical 1 line", true),
122 make_message(expired_per_chatty_message + 3, "test_tag", "duplicate"),
123 make_message(expired_per_chatty_message + 4, "test_tag", "normal"),
124 };
125 FixupMessages(&expected_log_messages);
126 auto flush_result = FlushMessages();
127 CompareLogMessages(expected_log_messages, flush_result.messages);
128 }
129
TEST_P(ChattyLogBufferTest,deduplication_liblog)130 TEST_P(ChattyLogBufferTest, deduplication_liblog) {
131 auto make_message = [&](uint32_t sec, int32_t tag, int32_t count) -> LogMessage {
132 logger_entry entry = {
133 .pid = 1, .tid = 1, .sec = sec, .nsec = 1, .lid = LOG_ID_EVENTS, .uid = 0};
134 android_log_event_int_t liblog_event = {
135 .header.tag = tag, .payload.type = EVENT_TYPE_INT, .payload.data = count};
136 return {entry, std::string(reinterpret_cast<char*>(&liblog_event), sizeof(liblog_event)),
137 false};
138 };
139
140 // LIBLOG_LOG_TAG
141 std::vector<LogMessage> log_messages = {
142 make_message(0, 1234, 1),
143 make_message(1, LIBLOG_LOG_TAG, 3),
144 make_message(2, 1234, 2),
145 make_message(3, LIBLOG_LOG_TAG, 3),
146 make_message(4, LIBLOG_LOG_TAG, 4),
147 make_message(5, 1234, 223),
148 make_message(6, LIBLOG_LOG_TAG, 2),
149 make_message(7, LIBLOG_LOG_TAG, 3),
150 make_message(8, LIBLOG_LOG_TAG, 4),
151 make_message(9, 1234, 227),
152 make_message(10, LIBLOG_LOG_TAG, 1),
153 make_message(11, LIBLOG_LOG_TAG, 3),
154 make_message(12, LIBLOG_LOG_TAG, 2),
155 make_message(13, LIBLOG_LOG_TAG, 3),
156 make_message(14, LIBLOG_LOG_TAG, 5),
157 make_message(15, 1234, 227),
158 make_message(16, LIBLOG_LOG_TAG, 2),
159 make_message(17, LIBLOG_LOG_TAG, std::numeric_limits<int32_t>::max()),
160 make_message(18, LIBLOG_LOG_TAG, 3),
161 make_message(19, LIBLOG_LOG_TAG, 5),
162 make_message(20, 1234, 227),
163 };
164 FixupMessages(&log_messages);
165 LogMessages(log_messages);
166
167 std::vector<LogMessage> expected_log_messages = {
168 make_message(0, 1234, 1),
169 make_message(1, LIBLOG_LOG_TAG, 3),
170 make_message(2, 1234, 2),
171 make_message(3, LIBLOG_LOG_TAG, 3),
172 make_message(4, LIBLOG_LOG_TAG, 4),
173 make_message(5, 1234, 223),
174 // More than 2 liblog events (3 here), sum their value into the third message.
175 make_message(6, LIBLOG_LOG_TAG, 2),
176 make_message(8, LIBLOG_LOG_TAG, 7),
177 make_message(9, 1234, 227),
178 // More than 2 liblog events (5 here), sum their value into the third message.
179 make_message(10, LIBLOG_LOG_TAG, 1),
180 make_message(14, LIBLOG_LOG_TAG, 13),
181 make_message(15, 1234, 227),
182 // int32_t max is the max for a chatty message, beyond that we must use new messages.
183 make_message(16, LIBLOG_LOG_TAG, 2),
184 make_message(17, LIBLOG_LOG_TAG, std::numeric_limits<int32_t>::max()),
185 make_message(19, LIBLOG_LOG_TAG, 8),
186 make_message(20, 1234, 227),
187 };
188 FixupMessages(&expected_log_messages);
189 auto flush_result = FlushMessages();
190 CompareLogMessages(expected_log_messages, flush_result.messages);
191 };
192
TEST_P(ChattyLogBufferTest,no_leading_chatty_simple)193 TEST_P(ChattyLogBufferTest, no_leading_chatty_simple) {
194 auto make_message = [&](uint32_t sec, int32_t pid, uint32_t uid, uint32_t lid, const char* tag,
195 const char* msg, bool regex = false) -> LogMessage {
196 logger_entry entry = {.pid = pid, .tid = 1, .sec = sec, .nsec = 1, .lid = lid, .uid = uid};
197 std::string message;
198 message.push_back(ANDROID_LOG_INFO);
199 message.append(tag);
200 message.push_back('\0');
201 message.append(msg);
202 message.push_back('\0');
203 return {entry, message, regex};
204 };
205
206 // clang-format off
207 std::vector<LogMessage> log_messages = {
208 make_message(1, 1, 1, LOG_ID_MAIN, "test_tag", "duplicate1"),
209 make_message(2, 2, 2, LOG_ID_SYSTEM, "test_tag", "duplicate2"),
210 make_message(3, 2, 2, LOG_ID_SYSTEM, "test_tag", "duplicate2"),
211 make_message(4, 2, 2, LOG_ID_SYSTEM, "test_tag", "duplicate2"),
212 make_message(6, 2, 2, LOG_ID_SYSTEM, "test_tag", "not duplicate2"),
213 make_message(7, 1, 1, LOG_ID_MAIN, "test_tag", "duplicate1"),
214 make_message(8, 1, 1, LOG_ID_MAIN, "test_tag", "duplicate1"),
215 make_message(9, 1, 1, LOG_ID_MAIN, "test_tag", "duplicate1"),
216 make_message(10, 1, 1, LOG_ID_MAIN, "test_tag", "not duplicate1"),
217 };
218 // clang-format on
219 FixupMessages(&log_messages);
220 LogMessages(log_messages);
221
222 // After logging log_messages, the below is what should be in the buffer:
223 // PID=1, LOG_ID_MAIN duplicate1
224 // [1] PID=2, LOG_ID_SYSTEM duplicate2
225 // PID=2, LOG_ID_SYSTEM chatty drop
226 // PID=2, LOG_ID_SYSTEM duplicate2
227 // PID=2, LOG_ID_SYSTEM not duplicate2
228 // [2] PID=1, LOG_ID_MAIN chatty drop
229 // [3] PID=1, LOG_ID_MAIN duplicate1
230 // PID=1, LOG_ID_MAIN not duplicate1
231
232 // We then read from the 2nd sequence number, starting from log message [1], but filtering out
233 // everything but PID=1, which results in us starting with log message [2], which is a chatty
234 // drop. Code prior to this test case would erroneously print it. The intended behavior that
235 // this test checks prints logs starting from log message [3].
236
237 // clang-format off
238 std::vector<LogMessage> expected_log_messages = {
239 make_message(9, 1, 1, LOG_ID_MAIN, "test_tag", "duplicate1"),
240 make_message(10, 1, 1, LOG_ID_MAIN, "test_tag", "not duplicate1"),
241 };
242 FixupMessages(&expected_log_messages);
243 // clang-format on
244
245 auto read_log_messages = ReadLogMessagesNonBlockingThread({.pid = 1, .sequence = 2});
246 CompareLogMessages(expected_log_messages, read_log_messages);
247 }
248
TEST_P(ChattyLogBufferTest,no_leading_chatty_tail)249 TEST_P(ChattyLogBufferTest, no_leading_chatty_tail) {
250 auto make_message = [&](uint32_t sec, const char* tag, const char* msg,
251 bool regex = false) -> LogMessage {
252 logger_entry entry = {
253 .pid = 1, .tid = 1, .sec = sec, .nsec = 1, .lid = LOG_ID_MAIN, .uid = 0};
254 std::string message;
255 message.push_back(ANDROID_LOG_INFO);
256 message.append(tag);
257 message.push_back('\0');
258 message.append(msg);
259 message.push_back('\0');
260 return {entry, message, regex};
261 };
262
263 // clang-format off
264 std::vector<LogMessage> log_messages = {
265 make_message(1, "test_tag", "duplicate"),
266 make_message(2, "test_tag", "duplicate"),
267 make_message(3, "test_tag", "duplicate"),
268 make_message(4, "test_tag", "not_duplicate"),
269 };
270 // clang-format on
271 FixupMessages(&log_messages);
272 LogMessages(log_messages);
273
274 // After logging log_messages, the below is what should be in the buffer:
275 // "duplicate"
276 // chatty
277 // "duplicate"
278 // "not duplicate"
279
280 // We then read the tail 3 messages expecting there to not be a chatty message, meaning that we
281 // should only see the last two messages.
282
283 // clang-format off
284 std::vector<LogMessage> expected_log_messages = {
285 make_message(3, "test_tag", "duplicate"),
286 make_message(4, "test_tag", "not_duplicate"),
287 };
288 FixupMessages(&expected_log_messages);
289 // clang-format on
290
291 auto read_log_messages = ReadLogMessagesNonBlockingThread({.tail = 3});
292 CompareLogMessages(expected_log_messages, read_log_messages);
293 }
294
295 INSTANTIATE_TEST_CASE_P(ChattyLogBufferTests, ChattyLogBufferTest, testing::Values("chatty"));
296