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 spdk_log_close(); 196 } 197 198 enum log_ext_state { 199 LOG_EXT_UNUSED, 200 LOG_EXT_OPENED, 201 LOG_EXT_USED, 202 LOG_EXT_CLOSED, 203 }; 204 205 enum log_ext_state g_log_state = LOG_EXT_UNUSED; 206 207 static void 208 log_ext_log_test(int level, const char *file, const int line, const char *func, 209 const char *format, va_list args) 210 { 211 g_log_state = LOG_EXT_USED; 212 } 213 214 static void 215 log_ext_open_test(void *ctx) 216 { 217 enum log_ext_state *state = ctx; 218 219 *state = LOG_EXT_OPENED; 220 } 221 222 static void 223 log_ext_close_test(void *ctx) 224 { 225 enum log_ext_state *state = ctx; 226 227 *state = LOG_EXT_CLOSED; 228 } 229 230 static void 231 log_ext_test(void) 232 { 233 struct spdk_log_opts opts = {.log = log_ext_log_test, .open = log_ext_open_test, .close = log_ext_close_test, .user_ctx = &g_log_state}; 234 opts.size = SPDK_SIZEOF(&opts, user_ctx); 235 236 CU_ASSERT(g_log_state == LOG_EXT_UNUSED); 237 spdk_log_open_ext(&opts); 238 CU_ASSERT(g_log_state == LOG_EXT_OPENED); 239 SPDK_WARNLOG("log warning unit test\n"); 240 CU_ASSERT(g_log_state == LOG_EXT_USED); 241 spdk_log_close(); 242 CU_ASSERT(g_log_state == LOG_EXT_CLOSED); 243 } 244 245 int 246 main(int argc, char **argv) 247 { 248 CU_pSuite suite = NULL; 249 unsigned int num_failures; 250 251 CU_initialize_registry(); 252 253 suite = CU_add_suite("log", NULL, NULL); 254 255 CU_ADD_TEST(suite, log_test); 256 CU_ADD_TEST(suite, deprecation); 257 CU_ADD_TEST(suite, log_ext_test); 258 259 num_failures = spdk_ut_run_tests(argc, argv, NULL); 260 CU_cleanup_registry(); 261 return num_failures; 262 } 263