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 "logging_splitters.h"
18 
19 #include <string>
20 #include <vector>
21 
22 #include <android-base/strings.h>
23 #include <gtest/gtest.h>
24 
25 namespace android {
26 namespace base {
27 
TestNewlineSplitter(const std::string & input,const std::vector<std::string> & expected_output)28 void TestNewlineSplitter(const std::string& input,
29                          const std::vector<std::string>& expected_output) {
30   std::vector<std::string> output;
31   auto logger_function = [&](const char* msg, int length) {
32     if (length == -1) {
33       output.push_back(msg);
34     } else {
35       output.push_back(std::string(msg, length));
36     }
37   };
38   SplitByLines(input.c_str(), logger_function);
39 
40   EXPECT_EQ(expected_output, output);
41 }
42 
TEST(logging_splitters,NewlineSplitter_EmptyString)43 TEST(logging_splitters, NewlineSplitter_EmptyString) {
44   TestNewlineSplitter("", std::vector<std::string>{""});
45 }
46 
TEST(logging_splitters,NewlineSplitter_BasicString)47 TEST(logging_splitters, NewlineSplitter_BasicString) {
48   TestNewlineSplitter("normal string", std::vector<std::string>{"normal string"});
49 }
50 
TEST(logging_splitters,NewlineSplitter_ormalBasicStringTrailingNewline)51 TEST(logging_splitters, NewlineSplitter_ormalBasicStringTrailingNewline) {
52   TestNewlineSplitter("normal string\n", std::vector<std::string>{"normal string", ""});
53 }
54 
TEST(logging_splitters,NewlineSplitter_MultilineTrailing)55 TEST(logging_splitters, NewlineSplitter_MultilineTrailing) {
56   TestNewlineSplitter("normal string\nsecond string\nthirdstring",
57                       std::vector<std::string>{"normal string", "second string", "thirdstring"});
58 }
59 
TEST(logging_splitters,NewlineSplitter_MultilineTrailingNewline)60 TEST(logging_splitters, NewlineSplitter_MultilineTrailingNewline) {
61   TestNewlineSplitter(
62       "normal string\nsecond string\nthirdstring\n",
63       std::vector<std::string>{"normal string", "second string", "thirdstring", ""});
64 }
65 
TEST(logging_splitters,NewlineSplitter_MultilineEmbeddedNewlines)66 TEST(logging_splitters, NewlineSplitter_MultilineEmbeddedNewlines) {
67   TestNewlineSplitter(
68       "normal string\n\n\nsecond string\n\nthirdstring\n",
69       std::vector<std::string>{"normal string", "", "", "second string", "", "thirdstring", ""});
70 }
71 
TestLogdChunkSplitter(const std::string & tag,const std::string & file,const std::string & input,const std::vector<std::string> & expected_output)72 void TestLogdChunkSplitter(const std::string& tag, const std::string& file,
73                            const std::string& input,
74                            const std::vector<std::string>& expected_output) {
75   std::vector<std::string> output;
76   auto logger_function = [&](LogId, LogSeverity, const char*, const char* msg) {
77     output.push_back(msg);
78   };
79 
80   SplitByLogdChunks(MAIN, FATAL, tag.c_str(), file.empty() ? nullptr : file.c_str(), 1000,
81                     input.c_str(), logger_function);
82 
83   auto return_lengths = [&] {
84     std::string sizes;
85     sizes += "expected_output sizes:";
86     for (const auto& string : expected_output) {
87       sizes += " " + std::to_string(string.size());
88     }
89     sizes += "\noutput sizes:";
90     for (const auto& string : output) {
91       sizes += " " + std::to_string(string.size());
92     }
93     return sizes;
94   };
95 
96   EXPECT_EQ(expected_output, output) << return_lengths();
97 }
98 
TEST(logging_splitters,LogdChunkSplitter_EmptyString)99 TEST(logging_splitters, LogdChunkSplitter_EmptyString) {
100   TestLogdChunkSplitter("tag", "", "", std::vector<std::string>{""});
101 }
102 
TEST(logging_splitters,LogdChunkSplitter_BasicString)103 TEST(logging_splitters, LogdChunkSplitter_BasicString) {
104   TestLogdChunkSplitter("tag", "", "normal string", std::vector<std::string>{"normal string"});
105 }
106 
TEST(logging_splitters,LogdChunkSplitter_NormalBasicStringTrailingNewline)107 TEST(logging_splitters, LogdChunkSplitter_NormalBasicStringTrailingNewline) {
108   TestLogdChunkSplitter("tag", "", "normal string\n", std::vector<std::string>{"normal string\n"});
109 }
110 
TEST(logging_splitters,LogdChunkSplitter_MultilineTrailing)111 TEST(logging_splitters, LogdChunkSplitter_MultilineTrailing) {
112   TestLogdChunkSplitter("tag", "", "normal string\nsecond string\nthirdstring",
113                         std::vector<std::string>{"normal string\nsecond string\nthirdstring"});
114 }
115 
TEST(logging_splitters,LogdChunkSplitter_MultilineTrailingNewline)116 TEST(logging_splitters, LogdChunkSplitter_MultilineTrailingNewline) {
117   TestLogdChunkSplitter("tag", "", "normal string\nsecond string\nthirdstring\n",
118                         std::vector<std::string>{"normal string\nsecond string\nthirdstring\n"});
119 }
120 
TEST(logging_splitters,LogdChunkSplitter_MultilineEmbeddedNewlines)121 TEST(logging_splitters, LogdChunkSplitter_MultilineEmbeddedNewlines) {
122   TestLogdChunkSplitter(
123       "tag", "", "normal string\n\n\nsecond string\n\nthirdstring\n",
124       std::vector<std::string>{"normal string\n\n\nsecond string\n\nthirdstring\n"});
125 }
126 
127 // This test should return the same string, the logd logger itself will truncate down to size.
128 // This has historically been the behavior both in libbase and liblog.
TEST(logging_splitters,LogdChunkSplitter_HugeLineNoNewline)129 TEST(logging_splitters, LogdChunkSplitter_HugeLineNoNewline) {
130   auto long_string = std::string(LOGGER_ENTRY_MAX_PAYLOAD, 'x');
131   ASSERT_EQ(LOGGER_ENTRY_MAX_PAYLOAD, static_cast<int>(long_string.size()));
132 
133   TestLogdChunkSplitter("tag", "", long_string, std::vector{long_string});
134 }
135 
ReduceToMaxSize(const std::string & tag,const std::string & string)136 std::string ReduceToMaxSize(const std::string& tag, const std::string& string) {
137   return string.substr(0, LOGGER_ENTRY_MAX_PAYLOAD - tag.size() - 35);
138 }
139 
TEST(logging_splitters,LogdChunkSplitter_MultipleHugeLineNoNewline)140 TEST(logging_splitters, LogdChunkSplitter_MultipleHugeLineNoNewline) {
141   auto long_string_x = std::string(LOGGER_ENTRY_MAX_PAYLOAD, 'x');
142   auto long_string_y = std::string(LOGGER_ENTRY_MAX_PAYLOAD, 'y');
143   auto long_string_z = std::string(LOGGER_ENTRY_MAX_PAYLOAD, 'z');
144 
145   auto long_strings = long_string_x + '\n' + long_string_y + '\n' + long_string_z;
146 
147   std::string tag = "tag";
148   std::vector expected = {ReduceToMaxSize(tag, long_string_x), ReduceToMaxSize(tag, long_string_y),
149                           long_string_z};
150 
151   TestLogdChunkSplitter(tag, "", long_strings, expected);
152 }
153 
154 // With a ~4k buffer, we should print 2 long strings per logger call.
TEST(logging_splitters,LogdChunkSplitter_Multiple2kLines)155 TEST(logging_splitters, LogdChunkSplitter_Multiple2kLines) {
156   std::vector expected = {
157       std::string(2000, 'a') + '\n' + std::string(2000, 'b'),
158       std::string(2000, 'c') + '\n' + std::string(2000, 'd'),
159       std::string(2000, 'e') + '\n' + std::string(2000, 'f'),
160   };
161 
162   auto long_strings = Join(expected, '\n');
163 
164   TestLogdChunkSplitter("tag", "", long_strings, expected);
165 }
166 
TEST(logging_splitters,LogdChunkSplitter_ExactSizedLines)167 TEST(logging_splitters, LogdChunkSplitter_ExactSizedLines) {
168   const char* tag = "tag";
169   ptrdiff_t max_size = LOGGER_ENTRY_MAX_PAYLOAD - strlen(tag) - 35;
170   auto long_string_a = std::string(max_size, 'a');
171   auto long_string_b = std::string(max_size, 'b');
172   auto long_string_c = std::string(max_size, 'c');
173 
174   auto long_strings = long_string_a + '\n' + long_string_b + '\n' + long_string_c;
175 
176   TestLogdChunkSplitter(tag, "", long_strings,
177                         std::vector{long_string_a, long_string_b, long_string_c});
178 }
179 
TEST(logging_splitters,LogdChunkSplitter_UnderEqualOver)180 TEST(logging_splitters, LogdChunkSplitter_UnderEqualOver) {
181   std::string tag = "tag";
182   ptrdiff_t max_size = LOGGER_ENTRY_MAX_PAYLOAD - tag.size() - 35;
183 
184   auto first_string_size = 1000;
185   auto first_string = std::string(first_string_size, 'a');
186   auto second_string_size = max_size - first_string_size - 1;
187   auto second_string = std::string(second_string_size, 'b');
188 
189   auto exact_string = std::string(max_size, 'c');
190 
191   auto large_string = std::string(max_size + 50, 'd');
192 
193   auto final_string = std::string("final string!\n\nfinal \n \n final \n");
194 
195   std::vector expected = {first_string + '\n' + second_string, exact_string,
196                           ReduceToMaxSize(tag, large_string), final_string};
197 
198   std::vector input_strings = {first_string + '\n' + second_string, exact_string, large_string,
199                                final_string};
200   auto long_strings = Join(input_strings, '\n');
201 
202   TestLogdChunkSplitter(tag, "", long_strings, expected);
203 }
204 
TEST(logging_splitters,LogdChunkSplitter_WithFile)205 TEST(logging_splitters, LogdChunkSplitter_WithFile) {
206   std::string tag = "tag";
207   std::string file = "/path/to/myfile.cpp";
208   int line = 1000;
209   auto file_header = StringPrintf("%s:%d] ", file.c_str(), line);
210   ptrdiff_t max_size = LOGGER_ENTRY_MAX_PAYLOAD - tag.size() - 35;
211 
212   auto first_string_size = 1000;
213   auto first_string = std::string(first_string_size, 'a');
214   auto second_string_size = max_size - first_string_size - 1 - 2 * file_header.size();
215   auto second_string = std::string(second_string_size, 'b');
216 
217   auto exact_string = std::string(max_size - file_header.size(), 'c');
218 
219   auto large_string = std::string(max_size + 50, 'd');
220 
221   auto final_string = std::string("final string!");
222 
223   std::vector expected = {
224       file_header + first_string + '\n' + file_header + second_string, file_header + exact_string,
225       file_header + ReduceToMaxSize(file_header + tag, large_string), file_header + final_string};
226 
227   std::vector input_strings = {first_string + '\n' + second_string, exact_string, large_string,
228                                final_string};
229   auto long_strings = Join(input_strings, '\n');
230 
231   TestLogdChunkSplitter(tag, file, long_strings, expected);
232 }
233 
234 // We set max_size based off of tag, so if it's too large, the buffer will be sized wrong.
235 // We could recover from this, but it's certainly an error for someone to attempt to use a tag this
236 // large, so we abort instead.
TEST(logging_splitters,LogdChunkSplitter_TooLongTag)237 TEST(logging_splitters, LogdChunkSplitter_TooLongTag) {
238   auto long_tag = std::string(5000, 'x');
239   auto logger_function = [](LogId, LogSeverity, const char*, const char*) {};
240   ASSERT_DEATH(
241       SplitByLogdChunks(MAIN, ERROR, long_tag.c_str(), nullptr, 0, "message", logger_function), "");
242 }
243 
244 // We do handle excessively large file names correctly however.
TEST(logging_splitters,LogdChunkSplitter_TooLongFile)245 TEST(logging_splitters, LogdChunkSplitter_TooLongFile) {
246   auto long_file = std::string(5000, 'x');
247   std::string tag = "tag";
248 
249   std::vector expected = {ReduceToMaxSize(tag, long_file), ReduceToMaxSize(tag, long_file)};
250 
251   TestLogdChunkSplitter(tag, long_file, "can't see me\nor me", expected);
252 }
253 
TestStderrOutputGenerator(const char * tag,const char * file,int line,const char * message,const std::string & expected)254 void TestStderrOutputGenerator(const char* tag, const char* file, int line, const char* message,
255                                const std::string& expected) {
256   // All log messages will show "01-01 00:00:00"
257   struct tm now = {
258       .tm_sec = 0,
259       .tm_min = 0,
260       .tm_hour = 0,
261       .tm_mday = 1,
262       .tm_mon = 0,
263       .tm_year = 1970,
264   };
265 
266   int pid = 1234;       // All log messages will have 1234 for their PID.
267   uint64_t tid = 4321;  // All log messages will have 4321 for their TID.
268 
269   auto result = StderrOutputGenerator(now, pid, tid, ERROR, tag, file, line, message);
270   EXPECT_EQ(expected, result);
271 }
272 
TEST(logging_splitters,StderrOutputGenerator_Basic)273 TEST(logging_splitters, StderrOutputGenerator_Basic) {
274   TestStderrOutputGenerator(nullptr, nullptr, 0, "simple message",
275                             "nullptr E 01-01 00:00:00  1234  4321 simple message\n");
276   TestStderrOutputGenerator("tag", nullptr, 0, "simple message",
277                             "tag E 01-01 00:00:00  1234  4321 simple message\n");
278   TestStderrOutputGenerator(
279       "tag", "/path/to/some/file", 0, "simple message",
280       "tag E 01-01 00:00:00  1234  4321 /path/to/some/file:0] simple message\n");
281 }
282 
TEST(logging_splitters,StderrOutputGenerator_NewlineTagAndFile)283 TEST(logging_splitters, StderrOutputGenerator_NewlineTagAndFile) {
284   TestStderrOutputGenerator("tag\n\n", nullptr, 0, "simple message",
285                             "tag\n\n E 01-01 00:00:00  1234  4321 simple message\n");
286   TestStderrOutputGenerator(
287       "tag", "/path/to/some/file\n\n", 0, "simple message",
288       "tag E 01-01 00:00:00  1234  4321 /path/to/some/file\n\n:0] simple message\n");
289 }
290 
TEST(logging_splitters,StderrOutputGenerator_TrailingNewLine)291 TEST(logging_splitters, StderrOutputGenerator_TrailingNewLine) {
292   TestStderrOutputGenerator(
293       "tag", nullptr, 0, "simple message\n",
294       "tag E 01-01 00:00:00  1234  4321 simple message\ntag E 01-01 00:00:00  1234  4321 \n");
295 }
296 
TEST(logging_splitters,StderrOutputGenerator_MultiLine)297 TEST(logging_splitters, StderrOutputGenerator_MultiLine) {
298   const char* expected_result =
299       "tag E 01-01 00:00:00  1234  4321 simple message\n"
300       "tag E 01-01 00:00:00  1234  4321 \n"
301       "tag E 01-01 00:00:00  1234  4321 \n"
302       "tag E 01-01 00:00:00  1234  4321 another message \n"
303       "tag E 01-01 00:00:00  1234  4321 \n"
304       "tag E 01-01 00:00:00  1234  4321  final message \n"
305       "tag E 01-01 00:00:00  1234  4321 \n"
306       "tag E 01-01 00:00:00  1234  4321 \n"
307       "tag E 01-01 00:00:00  1234  4321 \n";
308 
309   TestStderrOutputGenerator("tag", nullptr, 0,
310                             "simple message\n\n\nanother message \n\n final message \n\n\n",
311                             expected_result);
312 }
313 
TEST(logging_splitters,StderrOutputGenerator_MultiLineLong)314 TEST(logging_splitters, StderrOutputGenerator_MultiLineLong) {
315   auto long_string_a = std::string(4000, 'a');
316   auto long_string_b = std::string(4000, 'b');
317 
318   auto message = long_string_a + '\n' + long_string_b;
319   auto expected_result = "tag E 01-01 00:00:00  1234  4321 " + long_string_a + '\n' +
320                          "tag E 01-01 00:00:00  1234  4321 " + long_string_b + '\n';
321   TestStderrOutputGenerator("tag", nullptr, 0, message.c_str(), expected_result);
322 }
323 
324 }  // namespace base
325 }  // namespace android
326