1 // Copyright 2018 The Fuchsia Authors. All rights reserved.
2 // Use of this source code is governed by a BSD-style license that can be
3 // found in the LICENSE file.
4
5 #include <fbl/string.h>
6 #include <fbl/unique_fd.h>
7 #include <lib/zx/socket.h>
8 #include <lib/syslog/global.h>
9 #include <lib/syslog/wire_format.h>
10 #include <unittest/unittest.h>
11
12 #include <errno.h>
13 #include <fcntl.h>
14 #include <poll.h>
15 #include <string.h>
16 #include <unistd.h>
17
18 #include <utility>
19
20 __BEGIN_CDECLS
21
22 // This does not come from header file as this function should only be used in
23 // tests and is not for general use.
24 void fx_log_reset_global(void);
25
26 __END_CDECLS
27
init_helper(zx_handle_t handle,const char ** tags,size_t ntags)28 inline zx_status_t init_helper(zx_handle_t handle, const char** tags,
29 size_t ntags) {
30 fx_logger_config_t config = {.min_severity = FX_LOG_INFO,
31 .console_fd = -1,
32 .log_service_channel = handle,
33 .tags = tags,
34 .num_tags = ntags};
35
36 return fx_log_init_with_config(&config);
37 }
38
39 namespace {
40
41 class Cleanup {
42 public:
Cleanup()43 Cleanup() { fx_log_reset_global(); }
~Cleanup()44 ~Cleanup() { fx_log_reset_global(); }
45 };
46
47 } // namespace
48
ends_with(const char * str,const char * suffix)49 bool ends_with(const char* str, const char* suffix) {
50 size_t str_len = strlen(str);
51 size_t suffix_len = strlen(suffix);
52 if (str_len < suffix_len) {
53 return false;
54 }
55 str += str_len - suffix_len;
56 return strcmp(str, suffix) == 0;
57 }
58
output_compare_helper(zx::socket local,fx_log_severity_t severity,const char * msg,const char ** tags,int num_tags)59 bool output_compare_helper(zx::socket local, fx_log_severity_t severity,
60 const char* msg, const char** tags, int num_tags) {
61 fx_log_packet_t packet;
62 ASSERT_EQ(ZX_OK, local.read(0, &packet, sizeof(packet), nullptr));
63 EXPECT_EQ(severity, packet.metadata.severity);
64 int pos = 0;
65 for (int i = 0; i < num_tags; i++) {
66 const char* tag = tags[i];
67 auto tag_len = static_cast<int8_t>(strlen(tag));
68 ASSERT_EQ(tag_len, packet.data[pos]);
69 pos++;
70 ASSERT_BYTES_EQ((uint8_t*)tag, (uint8_t*)packet.data + pos, tag_len, "");
71 pos += tag_len;
72 }
73 ASSERT_EQ(0, packet.data[pos]);
74 pos++;
75 EXPECT_STR_EQ(msg, packet.data + pos, "");
76 return true;
77 }
78
TestLogSimpleWrite(void)79 bool TestLogSimpleWrite(void) {
80 BEGIN_TEST;
81 Cleanup cleanup;
82 zx::socket local, remote;
83 EXPECT_EQ(ZX_OK, zx::socket::create(ZX_SOCKET_DATAGRAM, &local, &remote));
84 ASSERT_EQ(ZX_OK, init_helper(remote.release(), nullptr, 0));
85 const char* msg = "test message";
86 FX_LOG(INFO, nullptr, msg);
87 output_compare_helper(std::move(local), FX_LOG_INFO, msg, nullptr, 0);
88 END_TEST;
89 }
90
TestLogWrite(void)91 bool TestLogWrite(void) {
92 BEGIN_TEST;
93 Cleanup cleanup;
94 zx::socket local, remote;
95 EXPECT_EQ(ZX_OK, zx::socket::create(ZX_SOCKET_DATAGRAM, &local, &remote));
96 ASSERT_EQ(ZX_OK, init_helper(remote.release(), nullptr, 0));
97 FX_LOGF(INFO, nullptr, "%d, %s", 10, "just some number");
98 output_compare_helper(std::move(local), FX_LOG_INFO, "10, just some number",
99 nullptr, 0);
100 END_TEST;
101 }
102
TestLogPreprocessedMessage(void)103 bool TestLogPreprocessedMessage(void) {
104 BEGIN_TEST;
105 Cleanup cleanup;
106 zx::socket local, remote;
107 EXPECT_EQ(ZX_OK, zx::socket::create(ZX_SOCKET_DATAGRAM, &local, &remote));
108 ASSERT_EQ(ZX_OK, init_helper(remote.release(), nullptr, 0));
109 FX_LOG(INFO, nullptr, "%d, %s");
110 output_compare_helper(std::move(local), FX_LOG_INFO, "%d, %s",
111 nullptr, 0);
112 END_TEST;
113 }
114
GetAvailableBytes(const zx::socket & socket,size_t * out_available)115 static zx_status_t GetAvailableBytes(const zx::socket& socket,
116 size_t* out_available) {
117 zx_info_socket_t info = {};
118 zx_status_t status = socket.get_info(ZX_INFO_SOCKET, &info, sizeof(info),
119 nullptr, nullptr);
120 if (status != ZX_OK) {
121 return status;
122 }
123 *out_available = info.rx_buf_available;
124 return ZX_OK;
125 }
126
TestLogSeverity(void)127 bool TestLogSeverity(void) {
128 BEGIN_TEST;
129 Cleanup cleanup;
130 zx::socket local, remote;
131 EXPECT_EQ(ZX_OK, zx::socket::create(ZX_SOCKET_DATAGRAM, &local, &remote));
132 ASSERT_EQ(ZX_OK, init_helper(remote.release(), nullptr, 0));
133
134 FX_LOG_SET_SEVERITY(WARNING);
135 FX_LOGF(INFO, nullptr, "%d, %s", 10, "just some number");
136 size_t outstanding_bytes = 10u; // init to non zero value.
137 ASSERT_EQ(ZX_OK, GetAvailableBytes(local, &outstanding_bytes));
138 EXPECT_EQ(0u, outstanding_bytes);
139
140 FX_LOGF(WARNING, nullptr, "%d, %s", 10, "just some number");
141 output_compare_helper(std::move(local), FX_LOG_WARNING,
142 "10, just some number", nullptr, 0);
143 END_TEST;
144 }
145
TestLogWriteWithTag(void)146 bool TestLogWriteWithTag(void) {
147 BEGIN_TEST;
148 Cleanup cleanup;
149 zx::socket local, remote;
150 EXPECT_EQ(ZX_OK, zx::socket::create(ZX_SOCKET_DATAGRAM, &local, &remote));
151 ASSERT_EQ(ZX_OK, init_helper(remote.release(), nullptr, 0));
152 FX_LOGF(INFO, "tag", "%d, %s", 10, "just some string");
153 const char* tags[] = {"tag"};
154 output_compare_helper(std::move(local), FX_LOG_INFO, "10, just some string",
155 tags, 1);
156 END_TEST;
157 }
158
TestLogWriteWithGlobalTag(void)159 bool TestLogWriteWithGlobalTag(void) {
160 BEGIN_TEST;
161 Cleanup cleanup;
162 zx::socket local, remote;
163 EXPECT_EQ(ZX_OK, zx::socket::create(ZX_SOCKET_DATAGRAM, &local, &remote));
164 const char* gtags[] = {"gtag"};
165 ASSERT_EQ(ZX_OK, init_helper(remote.release(), gtags, 1));
166 FX_LOGF(INFO, "tag", "%d, %s", 10, "just some string");
167 const char* tags[] = {"gtag", "tag"};
168 output_compare_helper(std::move(local), FX_LOG_INFO, "10, just some string",
169 tags, 2);
170 END_TEST;
171 }
172
TestLogWriteWithMultiGlobalTag(void)173 bool TestLogWriteWithMultiGlobalTag(void) {
174 BEGIN_TEST;
175 Cleanup cleanup;
176 zx::socket local, remote;
177 EXPECT_EQ(ZX_OK, zx::socket::create(ZX_SOCKET_DATAGRAM, &local, &remote));
178 const char* gtags[] = {"gtag", "gtag2"};
179 ASSERT_EQ(ZX_OK, init_helper(remote.release(), gtags, 2));
180 FX_LOGF(INFO, "tag", "%d, %s", 10, "just some string");
181 const char* tags[] = {"gtag", "gtag2", "tag"};
182 output_compare_helper(std::move(local), FX_LOG_INFO, "10, just some string",
183 tags, 3);
184 END_TEST;
185 }
186
TestLogFallback(void)187 bool TestLogFallback(void) {
188 BEGIN_TEST;
189 Cleanup cleanup;
190 zx::socket local, remote;
191 EXPECT_EQ(ZX_OK, zx::socket::create(ZX_SOCKET_DATAGRAM, &local, &remote));
192 const char* gtags[] = {"gtag", "gtag2"};
193 ASSERT_EQ(ZX_OK, init_helper(remote.release(), gtags, 2));
194
195 int pipefd[2];
196 EXPECT_EQ(pipe2(pipefd, O_NONBLOCK), 0);
197 fbl::unique_fd fd_to_close1(pipefd[0]);
198 fbl::unique_fd fd_to_close2(pipefd[1]);
199 fx_logger_activate_fallback(fx_log_get_logger(), pipefd[0]);
200
201 FX_LOGF(INFO, "tag", "%d, %s", 10, "just some string");
202
203 char buf[256];
204 size_t n = read(pipefd[1], buf, sizeof(buf));
205 EXPECT_GT(n, 0u);
206 buf[n] = 0;
207 EXPECT_TRUE(ends_with(buf, "[gtag, gtag2, tag] INFO: 10, just some string\n"), buf);
208 END_TEST;
209 }
210
TestMsgLengthLimit(void)211 bool TestMsgLengthLimit(void) {
212 BEGIN_TEST;
213 Cleanup cleanup;
214 zx::socket local, remote;
215 EXPECT_EQ(ZX_OK, zx::socket::create(ZX_SOCKET_DATAGRAM, &local, &remote));
216 const char* gtags[] = {"gtag", "gtag2"};
217 ASSERT_EQ(ZX_OK, init_helper(remote.release(), gtags, 2));
218 char msg[2048] = {0};
219 memset(msg, 'a', sizeof(msg) - 1);
220 FX_LOGF(INFO, "tag", "%s", msg);
221 fx_log_packet_t packet;
222 int msg_size = sizeof(packet.data) - 4 - 12;
223 char expected[msg_size];
224 memset(expected, 'a', msg_size - 4);
225 memset(expected + msg_size - 4, '.', 3);
226 expected[msg_size - 1] = 0;
227 const char* tags[] = {"gtag", "gtag2", "tag"};
228 output_compare_helper(std::move(local), FX_LOG_INFO, expected, tags, 3);
229 END_TEST;
230 }
231
TestMsgLengthLimitForPreprocessedMsg(void)232 bool TestMsgLengthLimitForPreprocessedMsg(void) {
233 BEGIN_TEST;
234 Cleanup cleanup;
235 zx::socket local, remote;
236 EXPECT_EQ(ZX_OK, zx::socket::create(ZX_SOCKET_DATAGRAM, &local, &remote));
237 const char* gtags[] = {"gtag", "gtag2"};
238 ASSERT_EQ(ZX_OK, init_helper(remote.release(), gtags, 2));
239 char msg[2048] = {0};
240 memset(msg, 'a', sizeof(msg) - 1);
241 msg[0] = '%';
242 msg[1] = 's';
243 FX_LOG(INFO, "tag", msg);
244 fx_log_packet_t packet;
245 int msg_size = sizeof(packet.data) - 4 - 12;
246 char expected[msg_size];
247 memset(expected, 'a', msg_size - 4);
248 expected[0] = '%';
249 expected[1] = 's';
250 memset(expected + msg_size - 4, '.', 3);
251 expected[msg_size - 1] = 0;
252 const char* tags[] = {"gtag", "gtag2", "tag"};
253 output_compare_helper(std::move(local), FX_LOG_INFO, expected, tags, 3);
254 END_TEST;
255 }
256
TestTagLengthLimit(void)257 bool TestTagLengthLimit(void) {
258 BEGIN_TEST;
259 Cleanup cleanup;
260 zx::socket local, remote;
261 EXPECT_EQ(ZX_OK, zx::socket::create(ZX_SOCKET_DATAGRAM, &local, &remote));
262 char gtags_buffer[FX_LOG_MAX_TAGS][FX_LOG_MAX_TAG_LEN + 1];
263 memset(gtags_buffer, 't', sizeof(gtags_buffer));
264 const char* gtags[FX_LOG_MAX_TAGS];
265 for (int i = 0; i < FX_LOG_MAX_TAGS; i++) {
266 gtags_buffer[i][0] = static_cast<char>(49 + i); // '1' + i
267 gtags_buffer[i][FX_LOG_MAX_TAG_LEN] = 0;
268 gtags[i] = gtags_buffer[i];
269 }
270 ASSERT_EQ(ZX_OK, init_helper(remote.release(), gtags, FX_LOG_MAX_TAGS));
271
272 char tag[FX_LOG_MAX_TAG_LEN + 1];
273 memcpy(tag, gtags[FX_LOG_MAX_TAGS - 1], sizeof(tag));
274 tag[0]++;
275 char msg[] = "some text";
276 FX_LOGF(INFO, tag, "%s", msg);
277 const char* tags[FX_LOG_MAX_TAGS + 1];
278 for (int i = 0; i < FX_LOG_MAX_TAGS; i++) {
279 gtags_buffer[i][FX_LOG_MAX_TAG_LEN - 1] = 0;
280 tags[i] = gtags_buffer[i];
281 }
282 tag[FX_LOG_MAX_TAG_LEN - 1] = 0;
283 tags[FX_LOG_MAX_TAGS] = tag;
284 output_compare_helper(std::move(local), FX_LOG_INFO, msg, tags,
285 FX_LOG_MAX_TAGS + 1);
286 END_TEST;
287 }
288
TestVlogSimpleWrite(void)289 bool TestVlogSimpleWrite(void) {
290 BEGIN_TEST;
291 Cleanup cleanup;
292 zx::socket local, remote;
293 EXPECT_EQ(ZX_OK, zx::socket::create(ZX_SOCKET_DATAGRAM, &local, &remote));
294 ASSERT_EQ(ZX_OK, init_helper(remote.release(), nullptr, 0));
295 const char* msg = "test message";
296 FX_LOG_SET_VERBOSITY(1);
297 FX_VLOG(1, nullptr, msg);
298 output_compare_helper(std::move(local), -1, msg, nullptr, 0);
299 END_TEST;
300 }
301
TestVlogWrite(void)302 bool TestVlogWrite(void) {
303 BEGIN_TEST;
304 Cleanup cleanup;
305 zx::socket local, remote;
306 EXPECT_EQ(ZX_OK, zx::socket::create(ZX_SOCKET_DATAGRAM, &local, &remote));
307 ASSERT_EQ(ZX_OK, init_helper(remote.release(), nullptr, 0));
308 FX_LOG_SET_VERBOSITY(1);
309 FX_VLOGF(1, nullptr, "%d, %s", 10, "just some number");
310 output_compare_helper(std::move(local), -1, "10, just some number",
311 nullptr, 0);
312 END_TEST;
313 }
314
TestVlogWriteWithTag(void)315 bool TestVlogWriteWithTag(void) {
316 BEGIN_TEST;
317 Cleanup cleanup;
318 zx::socket local, remote;
319 EXPECT_EQ(ZX_OK, zx::socket::create(ZX_SOCKET_DATAGRAM, &local, &remote));
320 ASSERT_EQ(ZX_OK, init_helper(remote.release(), nullptr, 0));
321 FX_LOG_SET_VERBOSITY(1);
322 FX_VLOGF(1, "tag", "%d, %s", 10, "just some string");
323 const char* tags[] = {"tag"};
324 output_compare_helper(std::move(local), -1, "10, just some string",
325 tags, 1);
326 END_TEST;
327 }
328
TestLogVerbosity(void)329 bool TestLogVerbosity(void) {
330 BEGIN_TEST;
331 Cleanup cleanup;
332 zx::socket local, remote;
333 EXPECT_EQ(ZX_OK, zx::socket::create(ZX_SOCKET_DATAGRAM, &local, &remote));
334 ASSERT_EQ(ZX_OK, init_helper(remote.release(), nullptr, 0));
335
336 FX_VLOGF(1, nullptr, "%d, %s", 10, "just some number");
337 size_t outstanding_bytes = 10u; // init to non zero value.
338 ASSERT_EQ(ZX_OK, GetAvailableBytes(local, &outstanding_bytes));
339 EXPECT_EQ(0u, outstanding_bytes);
340
341 FX_VLOGF(1, nullptr, "%d, %s", 10, "just some number");
342 outstanding_bytes = 10u; // init to non zero value.
343 ASSERT_EQ(ZX_OK, GetAvailableBytes(local, &outstanding_bytes));
344 EXPECT_EQ(0u, outstanding_bytes);
345
346 FX_LOG_SET_VERBOSITY(2);
347 FX_VLOGF(1, nullptr, "%d, %s", 10, "just some number");
348 output_compare_helper(std::move(local), -1,
349 "10, just some number", nullptr, 0);
350 END_TEST;
351 }
352
353 BEGIN_TEST_CASE(syslog_socket_tests)
354 RUN_TEST(TestLogSimpleWrite)
355 RUN_TEST(TestLogWrite)
356 RUN_TEST(TestLogPreprocessedMessage)
357 RUN_TEST(TestLogSeverity)
358 RUN_TEST(TestLogWriteWithTag)
359 RUN_TEST(TestLogWriteWithGlobalTag)
360 RUN_TEST(TestLogWriteWithMultiGlobalTag)
361 RUN_TEST(TestLogFallback)
362 RUN_TEST(TestVlogSimpleWrite)
363 RUN_TEST(TestVlogWrite)
364 RUN_TEST(TestVlogWriteWithTag)
365 RUN_TEST(TestLogVerbosity)
366 END_TEST_CASE(syslog_socket_tests)
367
368 BEGIN_TEST_CASE(syslog_socket_tests_edge_cases)
369 RUN_TEST(TestMsgLengthLimit)
370 RUN_TEST(TestTagLengthLimit)
371 RUN_TEST(TestMsgLengthLimitForPreprocessedMsg)
372 END_TEST_CASE(syslog_socket_tests_edge_cases)
373