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