1 // SPDX-License-Identifier: GPL-2.0+
2 /*
3  * Logging support test program
4  *
5  * Copyright (c) 2017 Google, Inc
6  * Written by Simon Glass <sjg@chromium.org>
7  */
8 
9 #include <common.h>
10 #include <command.h>
11 #include <log.h>
12 #include <asm/global_data.h>
13 #include <test/log.h>
14 #include <test/ut.h>
15 
16 DECLARE_GLOBAL_DATA_PTR;
17 
18 /* emit some sample log records in different ways, for testing */
do_log_run(struct unit_test_state * uts,int cat,const char * file)19 static int do_log_run(struct unit_test_state *uts, int cat, const char *file)
20 {
21 	int i;
22 	int ret, expected_ret;
23 
24 	if (gd->flags & GD_FLG_LOG_READY)
25 		expected_ret = 0;
26 	else
27 		expected_ret = -ENOSYS;
28 
29 	gd->log_fmt = LOGF_TEST;
30 	debug("debug\n");
31 	for (i = LOGL_FIRST; i < LOGL_COUNT; i++) {
32 		log(cat, i, "log %d\n", i);
33 		ret = _log(log_uc_cat(cat), i, file, 100 + i,
34 			   "func", "_log %d\n", i);
35 		ut_asserteq(ret, expected_ret);
36 	}
37 	/* test with LOGL_COUNT flag */
38 	for (i = LOGL_FIRST; i < LOGL_COUNT; i++) {
39 		ret = _log(log_uc_cat(cat), i | LOGL_FORCE_DEBUG, file, 100 + i,
40 			   "func", "_log force %d\n", i);
41 		ut_asserteq(ret, expected_ret);
42 	}
43 
44 	gd->log_fmt = log_get_default_format();
45 	return 0;
46 }
47 
48 #define log_run_cat(cat) do_log_run(uts, cat, "file")
49 #define log_run_file(file) do_log_run(uts, UCLASS_SPI, file)
50 #define log_run() do_log_run(uts, UCLASS_SPI, "file")
51 
52 #define EXPECT_LOG BIT(0)
53 #define EXPECT_DIRECT BIT(1)
54 #define EXPECT_EXTRA BIT(2)
55 #define EXPECT_FORCE BIT(3)
56 #define EXPECT_DEBUG BIT(4)
57 
do_check_log_entries(struct unit_test_state * uts,int flags,int min,int max)58 static int do_check_log_entries(struct unit_test_state *uts, int flags, int min,
59 				int max)
60 {
61 	int i;
62 
63 	for (i = min; i <= max; i++) {
64 		if (flags & EXPECT_LOG)
65 			ut_assert_nextline("          do_log_run() log %d", i);
66 		if (flags & EXPECT_DIRECT)
67 			ut_assert_nextline("                func() _log %d", i);
68 		if (flags & EXPECT_DEBUG) {
69 			ut_assert_nextline("log %d", i);
70 			ut_assert_nextline("_log %d", i);
71 		}
72 	}
73 	if (flags & EXPECT_EXTRA)
74 		for (; i <= LOGL_MAX ; i++)
75 			ut_assert_nextline("                func() _log %d", i);
76 
77 	for (i = LOGL_FIRST; i < LOGL_COUNT; i++) {
78 		if (flags & EXPECT_FORCE)
79 			ut_assert_nextline("                func() _log force %d",
80 					   i);
81 		if (flags & EXPECT_DEBUG)
82 			ut_assert_nextline("_log force %d", i);
83 	}
84 
85 	ut_assert_console_end();
86 	return 0;
87 }
88 
89 #define check_log_entries_flags_levels(flags, min, max) do {\
90 	int ret = do_check_log_entries(uts, flags, min, max); \
91 	if (ret) \
92 		return ret; \
93 } while (0)
94 
95 #define check_log_entries_flags(flags) \
96 	check_log_entries_flags_levels(flags, LOGL_FIRST, _LOG_MAX_LEVEL)
97 #define check_log_entries() check_log_entries_flags(EXPECT_LOG | EXPECT_DIRECT | EXPECT_FORCE)
98 #define check_log_entries_extra() \
99 	check_log_entries_flags(EXPECT_LOG | EXPECT_DIRECT | EXPECT_EXTRA | EXPECT_FORCE)
100 #define check_log_entries_none() check_log_entries_flags(EXPECT_FORCE)
101 
102 /* Check a category filter using the first category */
log_test_cat_allow(struct unit_test_state * uts)103 int log_test_cat_allow(struct unit_test_state *uts)
104 {
105 	enum log_category_t cat_list[] = {
106 		log_uc_cat(UCLASS_MMC), log_uc_cat(UCLASS_SPI),
107 		LOGC_NONE, LOGC_END
108 	};
109 	int filt;
110 
111 	filt = log_add_filter("console", cat_list, LOGL_MAX, NULL);
112 	ut_assert(filt >= 0);
113 
114 	ut_assertok(console_record_reset_enable());
115 	log_run_cat(UCLASS_MMC);
116 	check_log_entries_extra();
117 
118 	ut_assertok(console_record_reset_enable());
119 	log_run_cat(UCLASS_SPI);
120 	check_log_entries_extra();
121 
122 	ut_assertok(log_remove_filter("console", filt));
123 	return 0;
124 }
125 LOG_TEST_FLAGS(log_test_cat_allow, UT_TESTF_CONSOLE_REC);
126 
127 /* Check a category filter that should block log entries */
log_test_cat_deny_implicit(struct unit_test_state * uts)128 int log_test_cat_deny_implicit(struct unit_test_state *uts)
129 {
130 	enum log_category_t cat_list[] = {
131 		log_uc_cat(UCLASS_MMC),  LOGC_NONE, LOGC_END
132 	};
133 	int filt;
134 
135 	filt = log_add_filter("console", cat_list, LOGL_MAX, NULL);
136 	ut_assert(filt >= 0);
137 
138 	ut_assertok(console_record_reset_enable());
139 	log_run_cat(UCLASS_SPI);
140 	check_log_entries_none();
141 
142 	ut_assertok(log_remove_filter("console", filt));
143 	return 0;
144 }
145 LOG_TEST_FLAGS(log_test_cat_deny_implicit, UT_TESTF_CONSOLE_REC);
146 
147 /* Check passing and failing file filters */
log_test_file(struct unit_test_state * uts)148 int log_test_file(struct unit_test_state *uts)
149 {
150 	int filt;
151 
152 	filt = log_add_filter("console", NULL, LOGL_MAX, "file");
153 	ut_assert(filt >= 0);
154 
155 	ut_assertok(console_record_reset_enable());
156 	log_run_file("file");
157 	check_log_entries_flags(EXPECT_DIRECT | EXPECT_EXTRA | EXPECT_FORCE);
158 
159 	ut_assertok(console_record_reset_enable());
160 	log_run_file("file2");
161 	check_log_entries_none();
162 
163 	ut_assertok(log_remove_filter("console", filt));
164 	return 0;
165 }
166 LOG_TEST_FLAGS(log_test_file, UT_TESTF_CONSOLE_REC);
167 
168 /* Check a passing file filter (second in list) */
log_test_file_second(struct unit_test_state * uts)169 int log_test_file_second(struct unit_test_state *uts)
170 {
171 	int filt;
172 
173 	filt = log_add_filter("console", NULL, LOGL_MAX, "file,file2");
174 	ut_assert(filt >= 0);
175 
176 	ut_assertok(console_record_reset_enable());
177 	log_run_file("file2");
178 	check_log_entries_flags(EXPECT_DIRECT | EXPECT_EXTRA | EXPECT_FORCE);
179 
180 	ut_assertok(log_remove_filter("console", filt));
181 	return 0;
182 }
183 LOG_TEST_FLAGS(log_test_file_second, UT_TESTF_CONSOLE_REC);
184 
185 /* Check a passing file filter (middle of list) */
log_test_file_mid(struct unit_test_state * uts)186 int log_test_file_mid(struct unit_test_state *uts)
187 {
188 	int filt;
189 
190 	filt = log_add_filter("console", NULL, LOGL_MAX,
191 			      "file,file2,log/log_test.c");
192 	ut_assert(filt >= 0);
193 
194 	ut_assertok(console_record_reset_enable());
195 	log_run_file("file2");
196 	check_log_entries_extra();
197 
198 	ut_assertok(log_remove_filter("console", filt));
199 	return 0;
200 }
201 LOG_TEST_FLAGS(log_test_file_mid, UT_TESTF_CONSOLE_REC);
202 
203 /* Check a log level filter */
log_test_level(struct unit_test_state * uts)204 int log_test_level(struct unit_test_state *uts)
205 {
206 	int filt;
207 
208 	filt = log_add_filter("console", NULL, LOGL_WARNING, NULL);
209 	ut_assert(filt >= 0);
210 
211 	ut_assertok(console_record_reset_enable());
212 	log_run();
213 	check_log_entries_flags_levels(EXPECT_LOG | EXPECT_DIRECT | EXPECT_FORCE,
214 				       LOGL_FIRST, LOGL_WARNING);
215 
216 	ut_assertok(log_remove_filter("console", filt));
217 	return 0;
218 }
219 LOG_TEST_FLAGS(log_test_level, UT_TESTF_CONSOLE_REC);
220 
221 /* Check two filters, one of which passes everything */
log_test_double(struct unit_test_state * uts)222 int log_test_double(struct unit_test_state *uts)
223 {
224 	int filt1, filt2;
225 
226 	filt1 = log_add_filter("console", NULL, LOGL_WARNING, NULL);
227 	ut_assert(filt1 >= 0);
228 	filt2 = log_add_filter("console", NULL, LOGL_MAX, NULL);
229 	ut_assert(filt2 >= 0);
230 
231 	ut_assertok(console_record_reset_enable());
232 	log_run();
233 	check_log_entries_extra();
234 
235 	ut_assertok(log_remove_filter("console", filt1));
236 	ut_assertok(log_remove_filter("console", filt2));
237 	return 0;
238 }
239 LOG_TEST_FLAGS(log_test_double, UT_TESTF_CONSOLE_REC);
240 
241 /* Check three filters, which together pass everything */
log_test_triple(struct unit_test_state * uts)242 int log_test_triple(struct unit_test_state *uts)
243 {
244 	int filt1, filt2, filt3;
245 
246 	filt1 = log_add_filter("console", NULL, LOGL_MAX, "file)");
247 	ut_assert(filt1 >= 0);
248 	filt2 = log_add_filter("console", NULL, LOGL_MAX, "file2");
249 	ut_assert(filt2 >= 0);
250 	filt3 = log_add_filter("console", NULL, LOGL_MAX, "log/log_test.c");
251 	ut_assert(filt3 >= 0);
252 
253 	ut_assertok(console_record_reset_enable());
254 	log_run_file("file2");
255 	check_log_entries_extra();
256 
257 	ut_assertok(log_remove_filter("console", filt1));
258 	ut_assertok(log_remove_filter("console", filt2));
259 	ut_assertok(log_remove_filter("console", filt3));
260 	return 0;
261 }
262 LOG_TEST_FLAGS(log_test_triple, UT_TESTF_CONSOLE_REC);
263 
do_log_test_helpers(struct unit_test_state * uts)264 int do_log_test_helpers(struct unit_test_state *uts)
265 {
266 	int i;
267 
268 	ut_assertok(console_record_reset_enable());
269 	log_err("level %d\n", LOGL_EMERG);
270 	log_err("level %d\n", LOGL_ALERT);
271 	log_err("level %d\n", LOGL_CRIT);
272 	log_err("level %d\n", LOGL_ERR);
273 	log_warning("level %d\n", LOGL_WARNING);
274 	log_notice("level %d\n", LOGL_NOTICE);
275 	log_info("level %d\n", LOGL_INFO);
276 	log_debug("level %d\n", LOGL_DEBUG);
277 	log_content("level %d\n", LOGL_DEBUG_CONTENT);
278 	log_io("level %d\n", LOGL_DEBUG_IO);
279 
280 	for (i = LOGL_EMERG; i <= _LOG_MAX_LEVEL; i++)
281 		ut_assert_nextline("%*s() level %d", CONFIG_LOGF_FUNC_PAD,
282 				   __func__, i);
283 	ut_assert_console_end();
284 	return 0;
285 }
286 
log_test_helpers(struct unit_test_state * uts)287 int log_test_helpers(struct unit_test_state *uts)
288 {
289 	int ret;
290 
291 	gd->log_fmt = LOGF_TEST;
292 	ret = do_log_test_helpers(uts);
293 	gd->log_fmt = log_get_default_format();
294 	return ret;
295 }
296 LOG_TEST_FLAGS(log_test_helpers, UT_TESTF_CONSOLE_REC);
297 
do_log_test_disable(struct unit_test_state * uts)298 int do_log_test_disable(struct unit_test_state *uts)
299 {
300 	ut_assertok(console_record_reset_enable());
301 	log_err("default\n");
302 	ut_assert_nextline("%*s() default", CONFIG_LOGF_FUNC_PAD, __func__);
303 
304 	ut_assertok(log_device_set_enable(LOG_GET_DRIVER(console), false));
305 	log_err("disabled\n");
306 
307 	ut_assertok(log_device_set_enable(LOG_GET_DRIVER(console), true));
308 	log_err("enabled\n");
309 	ut_assert_nextline("%*s() enabled", CONFIG_LOGF_FUNC_PAD, __func__);
310 	ut_assert_console_end();
311 	return 0;
312 }
313 
log_test_disable(struct unit_test_state * uts)314 int log_test_disable(struct unit_test_state *uts)
315 {
316 	int ret;
317 
318 	gd->log_fmt = LOGF_TEST;
319 	ret = do_log_test_disable(uts);
320 	gd->log_fmt = log_get_default_format();
321 	return ret;
322 }
323 LOG_TEST_FLAGS(log_test_disable, UT_TESTF_CONSOLE_REC);
324 
325 /* Check denying based on category */
log_test_cat_deny(struct unit_test_state * uts)326 int log_test_cat_deny(struct unit_test_state *uts)
327 {
328 	int filt1, filt2;
329 	enum log_category_t cat_list[] = {
330 		log_uc_cat(UCLASS_SPI), LOGC_END
331 	};
332 
333 	filt1 = log_add_filter("console", cat_list, LOGL_MAX, NULL);
334 	ut_assert(filt1 >= 0);
335 	filt2 = log_add_filter_flags("console", cat_list, LOGL_MAX, NULL,
336 				     LOGFF_DENY);
337 	ut_assert(filt2 >= 0);
338 
339 	ut_assertok(console_record_reset_enable());
340 	log_run_cat(UCLASS_SPI);
341 	check_log_entries_none();
342 
343 	ut_assertok(log_remove_filter("console", filt1));
344 	ut_assertok(log_remove_filter("console", filt2));
345 	return 0;
346 }
347 LOG_TEST_FLAGS(log_test_cat_deny, UT_TESTF_CONSOLE_REC);
348 
349 /* Check denying based on file */
log_test_file_deny(struct unit_test_state * uts)350 int log_test_file_deny(struct unit_test_state *uts)
351 {
352 	int filt1, filt2;
353 
354 	filt1 = log_add_filter("console", NULL, LOGL_MAX, "file");
355 	ut_assert(filt1 >= 0);
356 	filt2 = log_add_filter_flags("console", NULL, LOGL_MAX, "file",
357 				     LOGFF_DENY);
358 	ut_assert(filt2 >= 0);
359 
360 	ut_assertok(console_record_reset_enable());
361 	log_run_file("file");
362 	check_log_entries_none();
363 
364 	ut_assertok(log_remove_filter("console", filt1));
365 	ut_assertok(log_remove_filter("console", filt2));
366 	return 0;
367 }
368 LOG_TEST_FLAGS(log_test_file_deny, UT_TESTF_CONSOLE_REC);
369 
370 /* Check denying based on level */
log_test_level_deny(struct unit_test_state * uts)371 int log_test_level_deny(struct unit_test_state *uts)
372 {
373 	int filt1, filt2;
374 
375 	filt1 = log_add_filter("console", NULL, LOGL_INFO, NULL);
376 	ut_assert(filt1 >= 0);
377 	filt2 = log_add_filter_flags("console", NULL, LOGL_WARNING, NULL,
378 				     LOGFF_DENY);
379 	ut_assert(filt2 >= 0);
380 
381 	ut_assertok(console_record_reset_enable());
382 	log_run();
383 	check_log_entries_flags_levels(EXPECT_LOG | EXPECT_DIRECT | EXPECT_FORCE,
384 				       LOGL_WARNING + 1, _LOG_MAX_LEVEL);
385 
386 	ut_assertok(log_remove_filter("console", filt1));
387 	ut_assertok(log_remove_filter("console", filt2));
388 	return 0;
389 }
390 LOG_TEST_FLAGS(log_test_level_deny, UT_TESTF_CONSOLE_REC);
391 
392 /* Check matching based on minimum level */
log_test_min(struct unit_test_state * uts)393 int log_test_min(struct unit_test_state *uts)
394 {
395 	int filt1, filt2;
396 
397 	filt1 = log_add_filter_flags("console", NULL, LOGL_WARNING, NULL,
398 				     LOGFF_LEVEL_MIN);
399 	ut_assert(filt1 >= 0);
400 	filt2 = log_add_filter_flags("console", NULL, LOGL_INFO, NULL,
401 				     LOGFF_DENY | LOGFF_LEVEL_MIN);
402 	ut_assert(filt2 >= 0);
403 
404 	ut_assertok(console_record_reset_enable());
405 	log_run();
406 	check_log_entries_flags_levels(EXPECT_LOG | EXPECT_DIRECT | EXPECT_FORCE,
407 				       LOGL_WARNING, LOGL_INFO - 1);
408 
409 	ut_assertok(log_remove_filter("console", filt1));
410 	ut_assertok(log_remove_filter("console", filt2));
411 	return 0;
412 }
413 LOG_TEST_FLAGS(log_test_min, UT_TESTF_CONSOLE_REC);
414 
415 /* Check dropped traces */
log_test_dropped(struct unit_test_state * uts)416 int log_test_dropped(struct unit_test_state *uts)
417 {
418 	/* force LOG not ready */
419 	gd->flags &= ~(GD_FLG_LOG_READY);
420 	gd->log_drop_count = 0;
421 
422 	ut_assertok(console_record_reset_enable());
423 	log_run();
424 
425 	ut_asserteq(gd->log_drop_count, 3 * (LOGL_COUNT - LOGL_FIRST - 1));
426 	check_log_entries_flags_levels(EXPECT_DEBUG, LOGL_FIRST, CONFIG_LOG_DEFAULT_LEVEL);
427 
428 	gd->flags |= GD_FLG_LOG_READY;
429 	gd->log_drop_count = 0;
430 
431 	return 0;
432 }
433 LOG_TEST_FLAGS(log_test_dropped, UT_TESTF_CONSOLE_REC);
434 
435 /* Check log_buffer() */
log_test_buffer(struct unit_test_state * uts)436 int log_test_buffer(struct unit_test_state *uts)
437 {
438 	u8 *buf;
439 	int i;
440 
441 	buf = malloc(0x20);
442 	ut_assertnonnull(buf);
443 	memset(buf, '\0', 0x20);
444 	for (i = 0; i < 0x11; i++)
445 		buf[i] = i * 0x11;
446 
447 	ut_assertok(console_record_reset_enable());
448 	log_buffer(LOGC_BOOT, LOGL_INFO, 0, buf, 1, 0x12, 0);
449 
450 	/* This one should product no output due to the debug level */
451 	log_buffer(LOGC_BOOT, LOGL_DEBUG, 0, buf, 1, 0x12, 0);
452 
453 	ut_assert_nextline("00000000: 00 11 22 33 44 55 66 77 88 99 aa bb cc dd ee ff  ..\"3DUfw........");
454 	ut_assert_nextline("00000010: 10 00                                            ..");
455 	ut_assert_console_end();
456 	free(buf);
457 
458 	return 0;
459 }
460 LOG_TEST_FLAGS(log_test_buffer, UT_TESTF_CONSOLE_REC);
461