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