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