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", i);
80 		if (flags & EXPECT_DEBUG)
81 			ut_assert_nextline("_log force %d", i);
82 	}
83 
84 	ut_assert_console_end();
85 	return 0;
86 }
87 
88 #define check_log_entries_flags_levels(flags, min, max) do {\
89 	int ret = do_check_log_entries(uts, flags, min, max); \
90 	if (ret) \
91 		return ret; \
92 } while (0)
93 
94 #define check_log_entries_flags(flags) \
95 	check_log_entries_flags_levels(flags, LOGL_FIRST, _LOG_MAX_LEVEL)
96 #define check_log_entries() check_log_entries_flags(EXPECT_LOG | EXPECT_DIRECT | EXPECT_FORCE)
97 #define check_log_entries_extra() \
98 	check_log_entries_flags(EXPECT_LOG | EXPECT_DIRECT | EXPECT_EXTRA | EXPECT_FORCE)
99 #define check_log_entries_none() check_log_entries_flags(EXPECT_FORCE)
100 
101 /* Check a category filter using the first category */
log_test_cat_allow(struct unit_test_state * uts)102 int log_test_cat_allow(struct unit_test_state *uts)
103 {
104 	enum log_category_t cat_list[] = {
105 		log_uc_cat(UCLASS_MMC), log_uc_cat(UCLASS_SPI),
106 		LOGC_NONE, LOGC_END
107 	};
108 	int filt;
109 
110 	filt = log_add_filter("console", cat_list, LOGL_MAX, NULL);
111 	ut_assert(filt >= 0);
112 
113 	ut_assertok(console_record_reset_enable());
114 	log_run_cat(UCLASS_MMC);
115 	check_log_entries_extra();
116 
117 	ut_assertok(console_record_reset_enable());
118 	log_run_cat(UCLASS_SPI);
119 	check_log_entries_extra();
120 
121 	ut_assertok(log_remove_filter("console", filt));
122 	return 0;
123 }
124 LOG_TEST_FLAGS(log_test_cat_allow, UT_TESTF_CONSOLE_REC);
125 
126 /* Check a category filter that should block log entries */
log_test_cat_deny_implicit(struct unit_test_state * uts)127 int log_test_cat_deny_implicit(struct unit_test_state *uts)
128 {
129 	enum log_category_t cat_list[] = {
130 		log_uc_cat(UCLASS_MMC),  LOGC_NONE, LOGC_END
131 	};
132 	int filt;
133 
134 	filt = log_add_filter("console", cat_list, LOGL_MAX, NULL);
135 	ut_assert(filt >= 0);
136 
137 	ut_assertok(console_record_reset_enable());
138 	log_run_cat(UCLASS_SPI);
139 	check_log_entries_none();
140 
141 	ut_assertok(log_remove_filter("console", filt));
142 	return 0;
143 }
144 LOG_TEST_FLAGS(log_test_cat_deny_implicit, UT_TESTF_CONSOLE_REC);
145 
146 /* Check passing and failing file filters */
log_test_file(struct unit_test_state * uts)147 int log_test_file(struct unit_test_state *uts)
148 {
149 	int filt;
150 
151 	filt = log_add_filter("console", NULL, LOGL_MAX, "file");
152 	ut_assert(filt >= 0);
153 
154 	ut_assertok(console_record_reset_enable());
155 	log_run_file("file");
156 	check_log_entries_flags(EXPECT_DIRECT | EXPECT_EXTRA | EXPECT_FORCE);
157 
158 	ut_assertok(console_record_reset_enable());
159 	log_run_file("file2");
160 	check_log_entries_none();
161 
162 	ut_assertok(log_remove_filter("console", filt));
163 	return 0;
164 }
165 LOG_TEST_FLAGS(log_test_file, UT_TESTF_CONSOLE_REC);
166 
167 /* Check a passing file filter (second in list) */
log_test_file_second(struct unit_test_state * uts)168 int log_test_file_second(struct unit_test_state *uts)
169 {
170 	int filt;
171 
172 	filt = log_add_filter("console", NULL, LOGL_MAX, "file,file2");
173 	ut_assert(filt >= 0);
174 
175 	ut_assertok(console_record_reset_enable());
176 	log_run_file("file2");
177 	check_log_entries_flags(EXPECT_DIRECT | EXPECT_EXTRA | EXPECT_FORCE);
178 
179 	ut_assertok(log_remove_filter("console", filt));
180 	return 0;
181 }
182 LOG_TEST_FLAGS(log_test_file_second, UT_TESTF_CONSOLE_REC);
183 
184 /* Check a passing file filter (middle of list) */
log_test_file_mid(struct unit_test_state * uts)185 int log_test_file_mid(struct unit_test_state *uts)
186 {
187 	int filt;
188 
189 	filt = log_add_filter("console", NULL, LOGL_MAX,
190 			      "file,file2,log/log_test.c");
191 	ut_assert(filt >= 0);
192 
193 	ut_assertok(console_record_reset_enable());
194 	log_run_file("file2");
195 	check_log_entries_extra();
196 
197 	ut_assertok(log_remove_filter("console", filt));
198 	return 0;
199 }
200 LOG_TEST_FLAGS(log_test_file_mid, UT_TESTF_CONSOLE_REC);
201 
202 /* Check a log level filter */
log_test_level(struct unit_test_state * uts)203 int log_test_level(struct unit_test_state *uts)
204 {
205 	int filt;
206 
207 	filt = log_add_filter("console", NULL, LOGL_WARNING, NULL);
208 	ut_assert(filt >= 0);
209 
210 	ut_assertok(console_record_reset_enable());
211 	log_run();
212 	check_log_entries_flags_levels(EXPECT_LOG | EXPECT_DIRECT | EXPECT_FORCE,
213 				       LOGL_FIRST, LOGL_WARNING);
214 
215 	ut_assertok(log_remove_filter("console", filt));
216 	return 0;
217 }
218 LOG_TEST_FLAGS(log_test_level, UT_TESTF_CONSOLE_REC);
219 
220 /* Check two filters, one of which passes everything */
log_test_double(struct unit_test_state * uts)221 int log_test_double(struct unit_test_state *uts)
222 {
223 	int filt1, filt2;
224 
225 	filt1 = log_add_filter("console", NULL, LOGL_WARNING, NULL);
226 	ut_assert(filt1 >= 0);
227 	filt2 = log_add_filter("console", NULL, LOGL_MAX, NULL);
228 	ut_assert(filt2 >= 0);
229 
230 	ut_assertok(console_record_reset_enable());
231 	log_run();
232 	check_log_entries_extra();
233 
234 	ut_assertok(log_remove_filter("console", filt1));
235 	ut_assertok(log_remove_filter("console", filt2));
236 	return 0;
237 }
238 LOG_TEST_FLAGS(log_test_double, UT_TESTF_CONSOLE_REC);
239 
240 /* Check three filters, which together pass everything */
log_test_triple(struct unit_test_state * uts)241 int log_test_triple(struct unit_test_state *uts)
242 {
243 	int filt1, filt2, filt3;
244 
245 	filt1 = log_add_filter("console", NULL, LOGL_MAX, "file)");
246 	ut_assert(filt1 >= 0);
247 	filt2 = log_add_filter("console", NULL, LOGL_MAX, "file2");
248 	ut_assert(filt2 >= 0);
249 	filt3 = log_add_filter("console", NULL, LOGL_MAX, "log/log_test.c");
250 	ut_assert(filt3 >= 0);
251 
252 	ut_assertok(console_record_reset_enable());
253 	log_run_file("file2");
254 	check_log_entries_extra();
255 
256 	ut_assertok(log_remove_filter("console", filt1));
257 	ut_assertok(log_remove_filter("console", filt2));
258 	ut_assertok(log_remove_filter("console", filt3));
259 	return 0;
260 }
261 LOG_TEST_FLAGS(log_test_triple, UT_TESTF_CONSOLE_REC);
262 
do_log_test_helpers(struct unit_test_state * uts)263 int do_log_test_helpers(struct unit_test_state *uts)
264 {
265 	int i;
266 
267 	ut_assertok(console_record_reset_enable());
268 	log_err("level %d\n", LOGL_EMERG);
269 	log_err("level %d\n", LOGL_ALERT);
270 	log_err("level %d\n", LOGL_CRIT);
271 	log_err("level %d\n", LOGL_ERR);
272 	log_warning("level %d\n", LOGL_WARNING);
273 	log_notice("level %d\n", LOGL_NOTICE);
274 	log_info("level %d\n", LOGL_INFO);
275 	log_debug("level %d\n", LOGL_DEBUG);
276 	log_content("level %d\n", LOGL_DEBUG_CONTENT);
277 	log_io("level %d\n", LOGL_DEBUG_IO);
278 
279 	for (i = LOGL_EMERG; i <= _LOG_MAX_LEVEL; i++)
280 		ut_assert_nextline("%s() level %d", __func__, i);
281 	ut_assert_console_end();
282 	return 0;
283 }
284 
log_test_helpers(struct unit_test_state * uts)285 int log_test_helpers(struct unit_test_state *uts)
286 {
287 	int ret;
288 
289 	gd->log_fmt = LOGF_TEST;
290 	ret = do_log_test_helpers(uts);
291 	gd->log_fmt = log_get_default_format();
292 	return ret;
293 }
294 LOG_TEST_FLAGS(log_test_helpers, UT_TESTF_CONSOLE_REC);
295 
do_log_test_disable(struct unit_test_state * uts)296 int do_log_test_disable(struct unit_test_state *uts)
297 {
298 	ut_assertok(console_record_reset_enable());
299 	log_err("default\n");
300 	ut_assert_nextline("%s() default", __func__);
301 
302 	ut_assertok(log_device_set_enable(LOG_GET_DRIVER(console), false));
303 	log_err("disabled\n");
304 
305 	ut_assertok(log_device_set_enable(LOG_GET_DRIVER(console), true));
306 	log_err("enabled\n");
307 	ut_assert_nextline("%s() enabled", __func__);
308 	ut_assert_console_end();
309 	return 0;
310 }
311 
log_test_disable(struct unit_test_state * uts)312 int log_test_disable(struct unit_test_state *uts)
313 {
314 	int ret;
315 
316 	gd->log_fmt = LOGF_TEST;
317 	ret = do_log_test_disable(uts);
318 	gd->log_fmt = log_get_default_format();
319 	return ret;
320 }
321 LOG_TEST_FLAGS(log_test_disable, UT_TESTF_CONSOLE_REC);
322 
323 /* Check denying based on category */
log_test_cat_deny(struct unit_test_state * uts)324 int log_test_cat_deny(struct unit_test_state *uts)
325 {
326 	int filt1, filt2;
327 	enum log_category_t cat_list[] = {
328 		log_uc_cat(UCLASS_SPI), LOGC_END
329 	};
330 
331 	filt1 = log_add_filter("console", cat_list, LOGL_MAX, NULL);
332 	ut_assert(filt1 >= 0);
333 	filt2 = log_add_filter_flags("console", cat_list, LOGL_MAX, NULL,
334 				     LOGFF_DENY);
335 	ut_assert(filt2 >= 0);
336 
337 	ut_assertok(console_record_reset_enable());
338 	log_run_cat(UCLASS_SPI);
339 	check_log_entries_none();
340 
341 	ut_assertok(log_remove_filter("console", filt1));
342 	ut_assertok(log_remove_filter("console", filt2));
343 	return 0;
344 }
345 LOG_TEST_FLAGS(log_test_cat_deny, UT_TESTF_CONSOLE_REC);
346 
347 /* Check denying based on file */
log_test_file_deny(struct unit_test_state * uts)348 int log_test_file_deny(struct unit_test_state *uts)
349 {
350 	int filt1, filt2;
351 
352 	filt1 = log_add_filter("console", NULL, LOGL_MAX, "file");
353 	ut_assert(filt1 >= 0);
354 	filt2 = log_add_filter_flags("console", NULL, LOGL_MAX, "file",
355 				     LOGFF_DENY);
356 	ut_assert(filt2 >= 0);
357 
358 	ut_assertok(console_record_reset_enable());
359 	log_run_file("file");
360 	check_log_entries_none();
361 
362 	ut_assertok(log_remove_filter("console", filt1));
363 	ut_assertok(log_remove_filter("console", filt2));
364 	return 0;
365 }
366 LOG_TEST_FLAGS(log_test_file_deny, UT_TESTF_CONSOLE_REC);
367 
368 /* Check denying based on level */
log_test_level_deny(struct unit_test_state * uts)369 int log_test_level_deny(struct unit_test_state *uts)
370 {
371 	int filt1, filt2;
372 
373 	filt1 = log_add_filter("console", NULL, LOGL_INFO, NULL);
374 	ut_assert(filt1 >= 0);
375 	filt2 = log_add_filter_flags("console", NULL, LOGL_WARNING, NULL,
376 				     LOGFF_DENY);
377 	ut_assert(filt2 >= 0);
378 
379 	ut_assertok(console_record_reset_enable());
380 	log_run();
381 	check_log_entries_flags_levels(EXPECT_LOG | EXPECT_DIRECT | EXPECT_FORCE,
382 				       LOGL_WARNING + 1, _LOG_MAX_LEVEL);
383 
384 	ut_assertok(log_remove_filter("console", filt1));
385 	ut_assertok(log_remove_filter("console", filt2));
386 	return 0;
387 }
388 LOG_TEST_FLAGS(log_test_level_deny, UT_TESTF_CONSOLE_REC);
389 
390 /* Check matching based on minimum level */
log_test_min(struct unit_test_state * uts)391 int log_test_min(struct unit_test_state *uts)
392 {
393 	int filt1, filt2;
394 
395 	filt1 = log_add_filter_flags("console", NULL, LOGL_WARNING, NULL,
396 				     LOGFF_LEVEL_MIN);
397 	ut_assert(filt1 >= 0);
398 	filt2 = log_add_filter_flags("console", NULL, LOGL_INFO, NULL,
399 				     LOGFF_DENY | LOGFF_LEVEL_MIN);
400 	ut_assert(filt2 >= 0);
401 
402 	ut_assertok(console_record_reset_enable());
403 	log_run();
404 	check_log_entries_flags_levels(EXPECT_LOG | EXPECT_DIRECT | EXPECT_FORCE,
405 				       LOGL_WARNING, LOGL_INFO - 1);
406 
407 	ut_assertok(log_remove_filter("console", filt1));
408 	ut_assertok(log_remove_filter("console", filt2));
409 	return 0;
410 }
411 LOG_TEST_FLAGS(log_test_min, UT_TESTF_CONSOLE_REC);
412 
413 /* Check dropped traces */
log_test_dropped(struct unit_test_state * uts)414 int log_test_dropped(struct unit_test_state *uts)
415 {
416 	/* force LOG not ready */
417 	gd->flags &= ~(GD_FLG_LOG_READY);
418 	gd->log_drop_count = 0;
419 
420 	ut_assertok(console_record_reset_enable());
421 	log_run();
422 
423 	ut_asserteq(gd->log_drop_count, 3 * (LOGL_COUNT - LOGL_FIRST - 1));
424 	check_log_entries_flags_levels(EXPECT_DEBUG, LOGL_FIRST, CONFIG_LOG_DEFAULT_LEVEL);
425 
426 	gd->flags |= GD_FLG_LOG_READY;
427 	gd->log_drop_count = 0;
428 
429 	return 0;
430 }
431 LOG_TEST_FLAGS(log_test_dropped, UT_TESTF_CONSOLE_REC);
432