Spdk/test/unit/lib/log/log.c/log_ut.c

/*   SPDX-License-Identifier: BSD-3-Clause
 *   Copyright (C) 2016 Intel Corporation.
 *   All rights reserved.
 */

#include "spdk/stdinc.h"

#include "spdk_cunit.h"
#include "spdk/log.h"
#include "spdk/env.h"
#include "spdk/string.h"

#include "log/log.c"
#include "log/log_flags.c"
#include "log/log_deprecated.c"

static void
log_test(void)
{
	spdk_log_set_level(SPDK_LOG_ERROR);
	CU_ASSERT_EQUAL(spdk_log_get_level(), SPDK_LOG_ERROR);
	spdk_log_set_level(SPDK_LOG_WARN);
	CU_ASSERT_EQUAL(spdk_log_get_level(), SPDK_LOG_WARN);
	spdk_log_set_level(SPDK_LOG_NOTICE);
	CU_ASSERT_EQUAL(spdk_log_get_level(), SPDK_LOG_NOTICE);
	spdk_log_set_level(SPDK_LOG_INFO);
	CU_ASSERT_EQUAL(spdk_log_get_level(), SPDK_LOG_INFO);
	spdk_log_set_level(SPDK_LOG_DEBUG);
	CU_ASSERT_EQUAL(spdk_log_get_level(), SPDK_LOG_DEBUG);

	spdk_log_set_print_level(SPDK_LOG_ERROR);
	CU_ASSERT_EQUAL(spdk_log_get_print_level(), SPDK_LOG_ERROR);
	spdk_log_set_print_level(SPDK_LOG_WARN);
	CU_ASSERT_EQUAL(spdk_log_get_print_level(), SPDK_LOG_WARN);
	spdk_log_set_print_level(SPDK_LOG_NOTICE);
	CU_ASSERT_EQUAL(spdk_log_get_print_level(), SPDK_LOG_NOTICE);
	spdk_log_set_print_level(SPDK_LOG_INFO);
	CU_ASSERT_EQUAL(spdk_log_get_print_level(), SPDK_LOG_INFO);
	spdk_log_set_print_level(SPDK_LOG_DEBUG);
	CU_ASSERT_EQUAL(spdk_log_get_print_level(), SPDK_LOG_DEBUG);

#ifdef DEBUG
	CU_ASSERT(spdk_log_get_flag("LOG") == false);

	spdk_log_set_flag("log");
	CU_ASSERT(spdk_log_get_flag("LOG") == true);

	spdk_log_clear_flag("LOG");
	CU_ASSERT(spdk_log_get_flag("LOG") == false);
#endif

	spdk_log_open(NULL);
	spdk_log_set_flag("log");
	SPDK_WARNLOG("log warning unit test\n");
	SPDK_DEBUGLOG(log, "log test\n");
	SPDK_LOGDUMP(log, "log dump test:", "log dump", 8);
	spdk_log_dump(stderr, "spdk dump test:", "spdk dump", 9);
	/* Test spdk_log_dump with more than 16 chars and less than 32 chars */
	spdk_log_dump(stderr, "spdk dump test:", "spdk dump 16 more chars", 23);

	spdk_log_close();
}

SPDK_LOG_DEPRECATION_REGISTER(unit_test_not_limited, "not rate limited", "never", 0)
SPDK_LOG_DEPRECATION_REGISTER(unit_test_limited, "with rate limit", "sometime", 1)
SPDK_LOG_DEPRECATION_REGISTER(unit_test_never_called, "not called", "maybe", 0)

int g_ut_dep_expect_line;
const char *g_ut_dep_expect_func;
const char *g_ut_dep_expect_msg;
uint32_t g_ut_dep_log_times;
bool g_ut_dep_saw_suppressed_log;

static void
log_deprecations(int level, const char *file, const int line, const char *func,
		 const char *format, va_list args)
{
	char *msg;

	g_ut_dep_log_times++;

	CU_ASSERT(level == SPDK_LOG_WARN);

	if (strcmp("spdk_log_deprecated", func) == 0) {
		g_ut_dep_saw_suppressed_log = true;
	} else {
		CU_ASSERT(strcmp(g_ut_dep_expect_func, func) == 0);
		CU_ASSERT(g_ut_dep_expect_line == line);
	}

	/* A "starts with" check */
	msg = spdk_vsprintf_alloc(format, args);
	SPDK_CU_ASSERT_FATAL(msg != NULL);
	CU_ASSERT(strncmp(g_ut_dep_expect_msg, msg, strlen(g_ut_dep_expect_msg)) == 0)

	free(msg);
}

bool g_found_not_limited;
bool g_found_limited;
bool g_found_never_called;

static int
iter_dep_cb(void *ctx, struct spdk_deprecation *dep)
{
	/* The getters work from the callback. */
	if (dep == _deprecated_unit_test_not_limited) {
		CU_ASSERT(!g_found_not_limited);
		g_found_not_limited = true;
		CU_ASSERT(strcmp(spdk_deprecation_get_tag(dep), "unit_test_not_limited") == 0);
		CU_ASSERT(strcmp(spdk_deprecation_get_description(dep), "not rate limited") == 0);
		CU_ASSERT(strcmp(spdk_deprecation_get_remove_release(dep), "never") == 0);
		CU_ASSERT(spdk_deprecation_get_hits(dep) != 0);
	} else if (dep == _deprecated_unit_test_limited) {
		CU_ASSERT(!g_found_limited);
		g_found_limited = true;
		CU_ASSERT(strcmp(spdk_deprecation_get_tag(dep), "unit_test_limited") == 0);
		CU_ASSERT(strcmp(spdk_deprecation_get_description(dep), "with rate limit") == 0);
		CU_ASSERT(strcmp(spdk_deprecation_get_remove_release(dep), "sometime") == 0);
		CU_ASSERT(spdk_deprecation_get_hits(dep) != 0);
	} else if (dep == _deprecated_unit_test_never_called) {
		CU_ASSERT(!g_found_never_called);
		g_found_never_called = true;
		CU_ASSERT(strcmp(spdk_deprecation_get_tag(dep), "unit_test_never_called") == 0);
		CU_ASSERT(strcmp(spdk_deprecation_get_description(dep), "not called") == 0);
		CU_ASSERT(strcmp(spdk_deprecation_get_remove_release(dep), "maybe") == 0);
		CU_ASSERT(spdk_deprecation_get_hits(dep) == 0);
	} else {
		CU_ASSERT(false);
	}

	return 0;
}

static void
deprecation(void)
{
	int rc;

	spdk_log_open(log_deprecations);

	/* A log message is emitted for every message without rate limiting. */
	g_ut_dep_saw_suppressed_log = false;
	g_ut_dep_log_times = 0;
	g_ut_dep_expect_func = __func__;
	g_ut_dep_expect_msg = "unit_test_not_limited:";
	g_ut_dep_expect_line = __LINE__ + 1;
	SPDK_LOG_DEPRECATED(unit_test_not_limited);
	CU_ASSERT(_deprecated_unit_test_not_limited->hits == 1);
	CU_ASSERT(_deprecated_unit_test_not_limited->deferred == 0);
	CU_ASSERT(g_ut_dep_log_times == 1);
	g_ut_dep_expect_line = __LINE__ + 1;
	SPDK_LOG_DEPRECATED(unit_test_not_limited);
	CU_ASSERT(_deprecated_unit_test_not_limited->hits == 2);
	CU_ASSERT(_deprecated_unit_test_not_limited->deferred == 0);
	CU_ASSERT(g_ut_dep_log_times == 2);
	CU_ASSERT(!g_ut_dep_saw_suppressed_log);

	/* Rate limiting keeps track of deferred messages */
	g_ut_dep_saw_suppressed_log = false;
	g_ut_dep_log_times = 0;
	g_ut_dep_expect_msg = "unit_test_limited:";
	g_ut_dep_expect_line = __LINE__ + 1;
	SPDK_LOG_DEPRECATED(unit_test_limited);
	CU_ASSERT(_deprecated_unit_test_limited->hits == 1);
	CU_ASSERT(_deprecated_unit_test_limited->deferred == 0);
	CU_ASSERT(g_ut_dep_log_times == 1);
	SPDK_LOG_DEPRECATED(unit_test_limited);
	CU_ASSERT(_deprecated_unit_test_limited->hits == 2);
	CU_ASSERT(_deprecated_unit_test_limited->deferred == 1);
	CU_ASSERT(g_ut_dep_log_times == 1);
	CU_ASSERT(!g_ut_dep_saw_suppressed_log);

	/* After a delay, the next log message prints the normal message followed by one that says
	 * that some messages were suppressed.
	 */
	g_ut_dep_saw_suppressed_log = false;
	sleep(1);
	g_ut_dep_expect_line = __LINE__ + 1;
	SPDK_LOG_DEPRECATED(unit_test_limited);
	CU_ASSERT(_deprecated_unit_test_limited->hits == 3);
	CU_ASSERT(_deprecated_unit_test_limited->deferred == 0);
	CU_ASSERT(g_ut_dep_log_times == 3);
	CU_ASSERT(g_ut_dep_saw_suppressed_log);

	/* spdk_log_for_each_deprecation() visits each registered deprecation */
	rc = spdk_log_for_each_deprecation(NULL, iter_dep_cb);
	CU_ASSERT(rc == 0);
	CU_ASSERT(g_found_not_limited);
	CU_ASSERT(g_found_limited);
	CU_ASSERT(g_found_never_called);

	g_log = NULL;
}

int
main(int argc, char **argv)
{
	CU_pSuite	suite = NULL;
	unsigned int	num_failures;

	CU_set_error_action(CUEA_ABORT);
	CU_initialize_registry();

	suite = CU_add_suite("log", NULL, NULL);

	CU_ADD_TEST(suite, log_test);
	CU_ADD_TEST(suite, deprecation);

	CU_basic_set_mode(CU_BRM_VERBOSE);
	CU_basic_run_tests();
	num_failures = CU_get_number_of_failures();
	CU_cleanup_registry();
	return num_failures;
}