test/log/log_test.c

   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 */
  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
  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 */
 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 */
 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 */
 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) */
 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) */
 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 */
 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 */
 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 */
 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
 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
 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
 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
 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 */
 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 */
 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 */
 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 */
 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 */
 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() */
 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);