1 /* SPDX-License-Identifier: BSD-3-Clause 2 * Copyright (C) 2016 Intel Corporation. 3 * All rights reserved. 4 */ 5 6 #include "spdk/stdinc.h" 7 8 #include "spdk_internal/cunit.h" 9 #include "spdk/log.h" 10 #include "spdk/env.h" 11 #include "spdk/string.h" 12 13 #include "log/log.c" 14 #include "log/log_flags.c" 15 #include "log/log_deprecated.c" 16 17 SPDK_LOG_REGISTER_COMPONENT(log) 18 19 static void 20 log_test(void) 21 { 22 spdk_log_set_level(SPDK_LOG_ERROR); 23 CU_ASSERT_EQUAL(spdk_log_get_level(), SPDK_LOG_ERROR); 24 spdk_log_set_level(SPDK_LOG_WARN); 25 CU_ASSERT_EQUAL(spdk_log_get_level(), SPDK_LOG_WARN); 26 spdk_log_set_level(SPDK_LOG_NOTICE); 27 CU_ASSERT_EQUAL(spdk_log_get_level(), SPDK_LOG_NOTICE); 28 spdk_log_set_level(SPDK_LOG_INFO); 29 CU_ASSERT_EQUAL(spdk_log_get_level(), SPDK_LOG_INFO); 30 spdk_log_set_level(SPDK_LOG_DEBUG); 31 CU_ASSERT_EQUAL(spdk_log_get_level(), SPDK_LOG_DEBUG); 32 33 spdk_log_set_print_level(SPDK_LOG_ERROR); 34 CU_ASSERT_EQUAL(spdk_log_get_print_level(), SPDK_LOG_ERROR); 35 spdk_log_set_print_level(SPDK_LOG_WARN); 36 CU_ASSERT_EQUAL(spdk_log_get_print_level(), SPDK_LOG_WARN); 37 spdk_log_set_print_level(SPDK_LOG_NOTICE); 38 CU_ASSERT_EQUAL(spdk_log_get_print_level(), SPDK_LOG_NOTICE); 39 spdk_log_set_print_level(SPDK_LOG_INFO); 40 CU_ASSERT_EQUAL(spdk_log_get_print_level(), SPDK_LOG_INFO); 41 spdk_log_set_print_level(SPDK_LOG_DEBUG); 42 CU_ASSERT_EQUAL(spdk_log_get_print_level(), SPDK_LOG_DEBUG); 43 44 #ifdef DEBUG 45 CU_ASSERT(spdk_log_get_flag("LOG") == false); 46 47 spdk_log_set_flag("log"); 48 CU_ASSERT(spdk_log_get_flag("LOG") == true); 49 50 spdk_log_clear_flag("LOG"); 51 CU_ASSERT(spdk_log_get_flag("LOG") == false); 52 #endif 53 54 spdk_log_open(NULL); 55 spdk_log_set_flag("log"); 56 SPDK_WARNLOG("log warning unit test\n"); 57 SPDK_DEBUGLOG(log, "log test\n"); 58 SPDK_LOGDUMP(log, "log dump test:", "log dump", 8); 59 spdk_log_dump(stderr, "spdk dump test:", "spdk dump", 9); 60 /* Test spdk_log_dump with more than 16 chars and less than 32 chars */ 61 spdk_log_dump(stderr, "spdk dump test:", "spdk dump 16 more chars", 23); 62 63 spdk_log_close(); 64 } 65 66 SPDK_LOG_DEPRECATION_REGISTER(unit_test_not_limited, "not rate limited", "never", 0) 67 SPDK_LOG_DEPRECATION_REGISTER(unit_test_limited, "with rate limit", "sometime", 1) 68 SPDK_LOG_DEPRECATION_REGISTER(unit_test_never_called, "not called", "maybe", 0) 69 70 int g_ut_dep_expect_line; 71 const char *g_ut_dep_expect_func; 72 const char *g_ut_dep_expect_msg; 73 uint32_t g_ut_dep_log_times; 74 bool g_ut_dep_saw_suppressed_log; 75 76 static void 77 log_deprecations(int level, const char *file, const int line, const char *func, 78 const char *format, va_list args) 79 { 80 char *msg; 81 82 g_ut_dep_log_times++; 83 84 CU_ASSERT(level == SPDK_LOG_WARN); 85 86 if (strcmp("spdk_log_deprecated", func) == 0) { 87 g_ut_dep_saw_suppressed_log = true; 88 } else { 89 CU_ASSERT(strcmp(g_ut_dep_expect_func, func) == 0); 90 CU_ASSERT(g_ut_dep_expect_line == line); 91 } 92 93 /* A "starts with" check */ 94 msg = spdk_vsprintf_alloc(format, args); 95 SPDK_CU_ASSERT_FATAL(msg != NULL); 96 CU_ASSERT(strncmp(g_ut_dep_expect_msg, msg, strlen(g_ut_dep_expect_msg)) == 0) 97 98 free(msg); 99 } 100 101 bool g_found_not_limited; 102 bool g_found_limited; 103 bool g_found_never_called; 104 105 static int 106 iter_dep_cb(void *ctx, struct spdk_deprecation *dep) 107 { 108 /* The getters work from the callback. */ 109 if (dep == _deprecated_unit_test_not_limited) { 110 CU_ASSERT(!g_found_not_limited); 111 g_found_not_limited = true; 112 CU_ASSERT(strcmp(spdk_deprecation_get_tag(dep), "unit_test_not_limited") == 0); 113 CU_ASSERT(strcmp(spdk_deprecation_get_description(dep), "not rate limited") == 0); 114 CU_ASSERT(strcmp(spdk_deprecation_get_remove_release(dep), "never") == 0); 115 CU_ASSERT(spdk_deprecation_get_hits(dep) != 0); 116 } else if (dep == _deprecated_unit_test_limited) { 117 CU_ASSERT(!g_found_limited); 118 g_found_limited = true; 119 CU_ASSERT(strcmp(spdk_deprecation_get_tag(dep), "unit_test_limited") == 0); 120 CU_ASSERT(strcmp(spdk_deprecation_get_description(dep), "with rate limit") == 0); 121 CU_ASSERT(strcmp(spdk_deprecation_get_remove_release(dep), "sometime") == 0); 122 CU_ASSERT(spdk_deprecation_get_hits(dep) != 0); 123 } else if (dep == _deprecated_unit_test_never_called) { 124 CU_ASSERT(!g_found_never_called); 125 g_found_never_called = true; 126 CU_ASSERT(strcmp(spdk_deprecation_get_tag(dep), "unit_test_never_called") == 0); 127 CU_ASSERT(strcmp(spdk_deprecation_get_description(dep), "not called") == 0); 128 CU_ASSERT(strcmp(spdk_deprecation_get_remove_release(dep), "maybe") == 0); 129 CU_ASSERT(spdk_deprecation_get_hits(dep) == 0); 130 } else { 131 CU_ASSERT(false); 132 } 133 134 return 0; 135 } 136 137 static void 138 deprecation(void) 139 { 140 int rc; 141 142 spdk_log_open(log_deprecations); 143 144 /* A log message is emitted for every message without rate limiting. */ 145 g_ut_dep_saw_suppressed_log = false; 146 g_ut_dep_log_times = 0; 147 g_ut_dep_expect_func = __func__; 148 g_ut_dep_expect_msg = "unit_test_not_limited:"; 149 g_ut_dep_expect_line = __LINE__ + 1; 150 SPDK_LOG_DEPRECATED(unit_test_not_limited); 151 CU_ASSERT(_deprecated_unit_test_not_limited->hits == 1); 152 CU_ASSERT(_deprecated_unit_test_not_limited->deferred == 0); 153 CU_ASSERT(g_ut_dep_log_times == 1); 154 g_ut_dep_expect_line = __LINE__ + 1; 155 SPDK_LOG_DEPRECATED(unit_test_not_limited); 156 CU_ASSERT(_deprecated_unit_test_not_limited->hits == 2); 157 CU_ASSERT(_deprecated_unit_test_not_limited->deferred == 0); 158 CU_ASSERT(g_ut_dep_log_times == 2); 159 CU_ASSERT(!g_ut_dep_saw_suppressed_log); 160 161 /* Rate limiting keeps track of deferred messages */ 162 g_ut_dep_saw_suppressed_log = false; 163 g_ut_dep_log_times = 0; 164 g_ut_dep_expect_msg = "unit_test_limited:"; 165 g_ut_dep_expect_line = __LINE__ + 1; 166 SPDK_LOG_DEPRECATED(unit_test_limited); 167 CU_ASSERT(_deprecated_unit_test_limited->hits == 1); 168 CU_ASSERT(_deprecated_unit_test_limited->deferred == 0); 169 CU_ASSERT(g_ut_dep_log_times == 1); 170 SPDK_LOG_DEPRECATED(unit_test_limited); 171 CU_ASSERT(_deprecated_unit_test_limited->hits == 2); 172 CU_ASSERT(_deprecated_unit_test_limited->deferred == 1); 173 CU_ASSERT(g_ut_dep_log_times == 1); 174 CU_ASSERT(!g_ut_dep_saw_suppressed_log); 175 176 /* After a delay, the next log message prints the normal message followed by one that says 177 * that some messages were suppressed. 178 */ 179 g_ut_dep_saw_suppressed_log = false; 180 sleep(1); 181 g_ut_dep_expect_line = __LINE__ + 1; 182 SPDK_LOG_DEPRECATED(unit_test_limited); 183 CU_ASSERT(_deprecated_unit_test_limited->hits == 3); 184 CU_ASSERT(_deprecated_unit_test_limited->deferred == 0); 185 CU_ASSERT(g_ut_dep_log_times == 3); 186 CU_ASSERT(g_ut_dep_saw_suppressed_log); 187 188 /* spdk_log_for_each_deprecation() visits each registered deprecation */ 189 rc = spdk_log_for_each_deprecation(NULL, iter_dep_cb); 190 CU_ASSERT(rc == 0); 191 CU_ASSERT(g_found_not_limited); 192 CU_ASSERT(g_found_limited); 193 CU_ASSERT(g_found_never_called); 194 195 g_log = NULL; 196 } 197 198 int 199 main(int argc, char **argv) 200 { 201 CU_pSuite suite = NULL; 202 unsigned int num_failures; 203 204 CU_initialize_registry(); 205 206 suite = CU_add_suite("log", NULL, NULL); 207 208 CU_ADD_TEST(suite, log_test); 209 CU_ADD_TEST(suite, deprecation); 210 211 num_failures = spdk_ut_run_tests(argc, argv, NULL); 212 CU_cleanup_registry(); 213 return num_failures; 214 } 215