diff --git a/src/core/log_default.c b/src/core/log_default.c index 8728c51f91e..b761a85a49a 100644 --- a/src/core/log_default.c +++ b/src/core/log_default.c @@ -93,7 +93,7 @@ get_timestamp_prefix(char *buf, size_t buf_size) * are formatted and inserted in the message. * * ASSUMPTIONS: - * - level >= CORE_LOG_LEVEL_FATAL && level <= CORE_LOG_LEVEL_DEBUG + * - level >= CORE_LOG_LEVEL_HARK && level <= CORE_LOG_LEVEL_DEBUG * - level <= Core_log_threshold[LOG_THRESHOLD] * - file == NULL || (file != NULL && function != NULL) */ diff --git a/src/test/Makefile b/src/test/Makefile index 748d9fd6259..e39efaaa792 100644 --- a/src/test/Makefile +++ b/src/test/Makefile @@ -23,7 +23,6 @@ OBJ_TESTS = \ obj_many_size_allocs\ obj_realloc\ obj_sync\ - \ obj_action\ obj_alloc\ obj_badblock\ @@ -109,6 +108,7 @@ OBJ_TESTS = \ OTHER_TESTS = \ arch_flags\ core_log_internal\ + core_log_default_function\ core_log_max\ checksum\ compat_incompat_features\ diff --git a/src/test/core_log_default_function/.gitignore b/src/test/core_log_default_function/.gitignore new file mode 100644 index 00000000000..5c484fc37a8 --- /dev/null +++ b/src/test/core_log_default_function/.gitignore @@ -0,0 +1 @@ +core_log_default_function diff --git a/src/test/core_log_default_function/Makefile b/src/test/core_log_default_function/Makefile new file mode 100644 index 00000000000..9d0d328c3b2 --- /dev/null +++ b/src/test/core_log_default_function/Makefile @@ -0,0 +1,17 @@ +# SPDX-License-Identifier: BSD-3-Clause +# Copyright 2024, Intel Corporation + +TARGET = core_log_default_function +OBJS = core_log_default_function.o + +BUILD_STATIC_DEBUG=n +BUILD_STATIC_NONDEBUG=n + +# 'internal' is required for proper mock integration +# 'debug' is required for debug version of core/log.o that provides +# implementation of 'out_log()' that is used by 'ut_log_function()' + +LIBPMEMCORE=internal-debug + +include ../Makefile.inc +LDFLAGS += $(call extract_funcs, core_log_default_function.c) diff --git a/src/test/core_log_default_function/TESTS.py b/src/test/core_log_default_function/TESTS.py new file mode 100755 index 00000000000..939ae671dd9 --- /dev/null +++ b/src/test/core_log_default_function/TESTS.py @@ -0,0 +1,40 @@ +#!../env.py +# SPDX-License-Identifier: BSD-3-Clause +# Copyright 2024, Intel Corporation +# + + +import testframework as t +from testframework import granularity as g + + +@g.require_granularity(g.ANY) +class CORE_LOG(t.BaseTest): + test_type = t.Short + + def run(self, ctx): + ctx.exec('core_log_default_function', self.test_case) + + +class TEST0(CORE_LOG): + test_case = 'test_default_function' + + +class TEST1(CORE_LOG): + test_case = 'test_default_function_bad_file_name' + + +class TEST2(CORE_LOG): + test_case = 'test_default_function_short_file_name' + + +class TEST3(CORE_LOG): + test_case = 'test_default_function_no_file_name' + + +class TEST4(CORE_LOG): + test_case = 'test_default_function_no_function_name' + + +class TEST5(CORE_LOG): + test_case = 'test_default_function_bad_timestamp' diff --git a/src/test/core_log_default_function/core_log_default_function.c b/src/test/core_log_default_function/core_log_default_function.c new file mode 100644 index 00000000000..b685b4be806 --- /dev/null +++ b/src/test/core_log_default_function/core_log_default_function.c @@ -0,0 +1,300 @@ +// SPDX-License-Identifier: BSD-3-Clause +/* Copyright 2024, Intel Corporation */ + +/* + * core_log_default_function.c -- unit test for core_log_default_function + */ + +#undef _GNU_SOURCE +#include +#include +#include + +#include "unittest.h" +#include "log_internal.h" +#include "log_default.h" + +#define NO_ARGS_CONSUMED 0 + +#define MESSAGE_MOCK ((char *)0x24689753) +#define TIMESTAMP "DUMMY TIMESTAMP" +#define FILE_NAME "dummy.c" +#define FILE_NAME_W_PATH "dummy_path/dummy_path/" FILE_NAME +#define FILE_INFO_ERROR "[file info error]: " +#define FUNCTION_NAME "dummy_func()" +#define FILE_INFO FILE_NAME ": 123: " FUNCTION_NAME ": " +#define LINE_NO 1357 + +static const char log_level_names[CORE_LOG_LEVEL_MAX][9] = { + [CORE_LOG_LEVEL_HARK] = "*HARK* ", + [CORE_LOG_LEVEL_FATAL] = "*FATAL* ", + [CORE_LOG_LEVEL_ERROR] = "*ERROR* ", + [CORE_LOG_LEVEL_WARNING] = "*WARN* ", + [CORE_LOG_LEVEL_NOTICE] = "*NOTE* ", + [CORE_LOG_LEVEL_INFO] = "*INFO* ", + [CORE_LOG_LEVEL_DEBUG] = "*DEBUG* ", +}; + +static const int log_level_syslog_severity[] = { + [CORE_LOG_LEVEL_HARK] = LOG_NOTICE, + [CORE_LOG_LEVEL_FATAL] = LOG_CRIT, + [CORE_LOG_LEVEL_ERROR] = LOG_ERR, + [CORE_LOG_LEVEL_WARNING] = LOG_WARNING, + [CORE_LOG_LEVEL_NOTICE] = LOG_NOTICE, + [CORE_LOG_LEVEL_INFO] = LOG_INFO, + [CORE_LOG_LEVEL_DEBUG] = LOG_DEBUG, +}; + +static struct { + const char *exp_log_level_name; + const char *exp_file_info; +} Common; + +char *Strchr_ret; + +FUNC_MOCK(strrchr, char *, const char *__s, int __c) +FUNC_MOCK_RUN_DEFAULT { + UT_ASSERTeq(__c, '/'); + return Strchr_ret; +} +FUNC_MOCK_END + +static bool Os_clock_gettime_force_error; + +FUNC_MOCK(clock_gettime, int, clockid_t __clock_id, struct timespec *__tp) +FUNC_MOCK_RUN_DEFAULT { + if (Os_clock_gettime_force_error) + return -1; + return _FUNC_REAL(clock_gettime)(__clock_id, __tp); +} +FUNC_MOCK_END + +static struct { + const char *exp_file_name; + int ret; +} Snprintf; + +FUNC_MOCK(snprintf, int, char *__restrict __s, size_t __maxlen, + const char *__restrict __format, ...) +/* file info */ + FUNC_MOCK_RUN(0) { + va_list arg; + va_start(arg, __format); + UT_ASSERTstreq(__format, "%s: %3d: %s: "); + char *file_name = va_arg(arg, char *); + UT_ASSERTstreq(file_name, Snprintf.exp_file_name); + int line_no = va_arg(arg, int); + UT_ASSERTeq(line_no, LINE_NO); + char *function_name = va_arg(arg, char *); + UT_ASSERTstreq(function_name, FUNCTION_NAME); + /* Can we access the whole given buffer (*__s) */ + *(__s + __maxlen - 1) = '\0'; + va_end(arg); + + if (Snprintf.ret != 0) + return Snprintf.ret; + UT_ASSERT(sizeof(FILE_INFO) <= __maxlen); + strncpy(__s, FILE_INFO, __maxlen); + return sizeof(FILE_INFO) - 1; + } +/* get time prefix */ + FUNC_MOCK_RUN(1) { + UT_ASSERTstreq(__format, "%s.%06ld "); + UT_ASSERT(sizeof(TIMESTAMP) <= __maxlen); + strncpy(__s, TIMESTAMP, __maxlen); + return sizeof(TIMESTAMP) - 1; + } +FUNC_MOCK_RUN_DEFAULT { + UT_FATAL("Unexpected #%d sprintf: %s", RCOUNTER(snprintf), __format); +} +FUNC_MOCK_END + +static struct { + int exp__pri; +} Syslog; + +FUNC_MOCK(syslog, void, int __pri, const char *__fmt, ...) +FUNC_MOCK_RUN_DEFAULT { + UT_ASSERTeq(__pri, Syslog.exp__pri); + UT_ASSERTstreq(__fmt, "%s%s%s"); + va_list arg; + va_start(arg, __fmt); + char *log_level_name = va_arg(arg, char *); + UT_ASSERTstreq(log_level_name, Common.exp_log_level_name); + char *file_info = va_arg(arg, char *); + UT_ASSERTstreq(file_info, Common.exp_file_info); + char *message = va_arg(arg, char *); + UT_ASSERTeq(message, MESSAGE_MOCK); + va_end(arg); +} +FUNC_MOCK_END + +static struct { + char *exp_times_stamp; +} Fprintf; + +FUNC_MOCK(fprintf, int, FILE *__restrict __stream, const char *__restrict __fmt, + ...) +FUNC_MOCK_RUN_DEFAULT { + UT_ASSERTeq(__stream, stderr); + UT_ASSERTstreq(__fmt, "%s[%ld] %s%s%s\n"); + va_list arg; + va_start(arg, __fmt); + char *times_tamp = va_arg(arg, char *); + UT_ASSERTstreq(times_tamp, Fprintf.exp_times_stamp); + va_arg(arg, int); /* skip syscall(SYS_gettid) */ + char *log_level_name = va_arg(arg, char *); + UT_ASSERTstreq(log_level_name, Common.exp_log_level_name); + char *file_info = va_arg(arg, char *); + UT_ASSERTstreq(file_info, Common.exp_file_info); + char *message = va_arg(arg, char *); + UT_ASSERTeq(message, MESSAGE_MOCK); + va_end(arg); + return 0; +} +FUNC_MOCK_END + +/* Tests' helpers */ +#define TEST_SETUP() core_log_set_threshold(CORE_LOG_THRESHOLD_AUX, \ + CORE_LOG_LEVEL_DEBUG) + +#define TEST_STEP_SETUP(_LEVEL, _FILE_NAME_SHORT) \ + do { \ + FUNC_MOCK_RCOUNTER_SET(snprintf, 0); \ + FUNC_MOCK_RCOUNTER_SET(syslog, 0); \ + FUNC_MOCK_RCOUNTER_SET(fprintf, 0); \ + Strchr_ret = "/"_FILE_NAME_SHORT; \ + Common.exp_log_level_name = log_level_names[_LEVEL]; \ + Common.exp_file_info = FILE_INFO; \ + Snprintf.exp_file_name = _FILE_NAME_SHORT; \ + Snprintf.ret = 0; \ + Syslog.exp__pri = log_level_syslog_severity[_LEVEL]; \ + Fprintf.exp_times_stamp = TIMESTAMP; \ + } while (0) + +#define TEST_STEP_CHECK(_SNPRINTF, _FPRINTF) \ + do { \ + UT_ASSERTeq(RCOUNTER(syslog), 1); \ + UT_ASSERTeq(RCOUNTER(snprintf), _SNPRINTF); \ + UT_ASSERTeq(RCOUNTER(fprintf), _FPRINTF); \ + } while (0) + +/* basic test with a normal message pass through */ +static int +test_default_function(const struct test_case *tc, int argc, char *argv[]) +{ + TEST_SETUP(); + for (enum core_log_level treshold = CORE_LOG_LEVEL_HARK; + treshold < CORE_LOG_LEVEL_MAX; treshold++) { + core_log_set_threshold(CORE_LOG_THRESHOLD_AUX, treshold); + for (enum core_log_level level = CORE_LOG_LEVEL_HARK; + level < CORE_LOG_LEVEL_MAX; level++) { + TEST_STEP_SETUP(level, FILE_NAME); + core_log_default_function(NULL, level, FILE_NAME_W_PATH, + LINE_NO, FUNCTION_NAME, MESSAGE_MOCK); + if (level == CORE_LOG_LEVEL_HARK || level > treshold) + TEST_STEP_CHECK(1, 0); + else + TEST_STEP_CHECK(2, 1); + } + } + + return NO_ARGS_CONSUMED; +} + +/* test to check that information about a bad file is printed */ +static int +test_default_function_bad_file_name(const struct test_case *tc, int argc, + char *argv[]) +{ + TEST_SETUP(); + TEST_STEP_SETUP(CORE_LOG_LEVEL_DEBUG, FILE_INFO_ERROR); + Snprintf.ret = -1; + Common.exp_file_info = FILE_INFO_ERROR; + core_log_default_function(NULL, CORE_LOG_LEVEL_DEBUG, FILE_NAME_W_PATH, + LINE_NO, FUNCTION_NAME, MESSAGE_MOCK); + TEST_STEP_CHECK(2, 1); + + return NO_ARGS_CONSUMED; +} + +/* test to check that short file name (w/o path) is properly printed */ +static int +test_default_function_short_file_name(const struct test_case *tc, int argc, + char *argv[]) +{ + core_log_set_threshold(CORE_LOG_THRESHOLD_AUX, CORE_LOG_LEVEL_DEBUG); + TEST_SETUP(); + TEST_STEP_SETUP(CORE_LOG_LEVEL_DEBUG, FILE_NAME); + Strchr_ret = NULL; + core_log_default_function(NULL, CORE_LOG_LEVEL_DEBUG, FILE_NAME, + LINE_NO, FUNCTION_NAME, MESSAGE_MOCK); + TEST_STEP_CHECK(2, 1); + + return NO_ARGS_CONSUMED; +} + +/* test to check no fileinfo when file_name is NULL */ +static int +test_default_function_no_file_name(const struct test_case *tc, int argc, + char *argv[]) +{ + TEST_SETUP(); + TEST_STEP_SETUP(CORE_LOG_LEVEL_DEBUG, ""); + FUNC_MOCK_RCOUNTER_SET(snprintf, 1); /* skip file_info snprintf() */ + Common.exp_file_info = ""; + core_log_default_function(NULL, CORE_LOG_LEVEL_DEBUG, NULL, + LINE_NO, FUNCTION_NAME, MESSAGE_MOCK); + TEST_STEP_CHECK(2, 1); + + return NO_ARGS_CONSUMED; +} + +/* test to check no fileinfo when file_name and function_name are NULL */ +static int +test_default_function_no_function_name(const struct test_case *tc, int argc, + char *argv[]) +{ + TEST_SETUP(); + TEST_STEP_SETUP(CORE_LOG_LEVEL_DEBUG, ""); + FUNC_MOCK_RCOUNTER_SET(snprintf, 1); /* skip file_info snprintf() */ + Common.exp_file_info = ""; + core_log_default_function(NULL, CORE_LOG_LEVEL_DEBUG, NULL, + LINE_NO, NULL, MESSAGE_MOCK); + TEST_STEP_CHECK(2, 1); + + return NO_ARGS_CONSUMED; +} + +/* test to check timestamp error */ +static int +test_default_function_bad_timestamp(const struct test_case *tc, int argc, + char *argv[]) +{ + TEST_SETUP(); + TEST_STEP_SETUP(CORE_LOG_LEVEL_DEBUG, FILE_NAME); + Os_clock_gettime_force_error = true; /* fail the file_info snprintf() */ + Fprintf.exp_times_stamp = "[time error] "; + core_log_default_function(NULL, CORE_LOG_LEVEL_DEBUG, FILE_NAME, + LINE_NO, FUNCTION_NAME, MESSAGE_MOCK); + TEST_STEP_CHECK(1, 1); + + return NO_ARGS_CONSUMED; +} + +static struct test_case test_cases[] = { + TEST_CASE(test_default_function), + TEST_CASE(test_default_function_bad_file_name), + TEST_CASE(test_default_function_short_file_name), + TEST_CASE(test_default_function_no_file_name), + TEST_CASE(test_default_function_no_function_name), + TEST_CASE(test_default_function_bad_timestamp), +}; + +int +main(int argc, char *argv[]) +{ + START(argc, argv, "core_log_default_function"); + TEST_CASE_PROCESS(argc, argv, test_cases, ARRAY_SIZE(test_cases)); + DONE(NULL); +} diff --git a/src/test/core_log_internal/Makefile b/src/test/core_log_internal/Makefile index 221ebfd1f7b..1fe8a911bd3 100644 --- a/src/test/core_log_internal/Makefile +++ b/src/test/core_log_internal/Makefile @@ -7,7 +7,9 @@ OBJS = core_log_internal.o BUILD_STATIC_DEBUG=n BUILD_STATIC_NONDEBUG=n -# `internal` is required for proper mock integration +# 'internal' is required for proper mock integration +# 'nondebug' is required for proper execution of test_CORE_LOG_TRESHOLD_DEFAULT +# (use nondebug version of core/log.o) LIBPMEMCORE=internal-nondebug include ../Makefile.inc diff --git a/src/test/unittest/unittest.h b/src/test/unittest/unittest.h index f865c2d07cc..78d144a52d4 100644 --- a/src/test/unittest/unittest.h +++ b/src/test/unittest/unittest.h @@ -173,29 +173,35 @@ ut_log_function(void *context, enum core_log_level level, const char *file_name, /* * assertions... */ +#define UT_ASSERT_MSG(FORMAT, ...) \ + UT_FATAL("assertion failure: " FORMAT, ##__VA_ARGS__) /* assert a condition is true at runtime */ #define UT_ASSERT_rt(cnd)\ - ((void)((cnd) || (ut_fatal(__FILE__, __LINE__, __func__,\ - "assertion failure: %s", #cnd), 0))) + ((void)((cnd) || (UT_ASSERT_MSG("%s", #cnd), 0))) /* assertion with extra info printed if assertion fails at runtime */ #define UT_ASSERTinfo_rt(cnd, info) \ - ((void)((cnd) || (ut_fatal(__FILE__, __LINE__, __func__,\ - "assertion failure: %s (%s)", #cnd, info), 0))) + ((void)((cnd) || (UT_ASSERT_MSG("%s (%s)", #cnd, info), 0))) /* assert two integer values are equal at runtime */ -#define UT_ASSERTeq_rt(lhs, rhs)\ - ((void)(((lhs) == (rhs)) || (ut_fatal(__FILE__, __LINE__, __func__,\ - "assertion failure: %s (0x%llx) == %s (0x%llx)", #lhs,\ +#define UT_ASSERTeq_rt(lhs, rhs) \ + ((void)(((lhs) == (rhs)) || \ + (UT_ASSERT_MSG("%s (0x%llx) == %s (0x%llx)", #lhs, \ (unsigned long long)(lhs), #rhs, (unsigned long long)(rhs)), 0))) /* assert two integer values are not equal at runtime */ -#define UT_ASSERTne_rt(lhs, rhs)\ - ((void)(((lhs) != (rhs)) || (ut_fatal(__FILE__, __LINE__, __func__,\ - "assertion failure: %s (0x%llx) != %s (0x%llx)", #lhs,\ +#define UT_ASSERTne_rt(lhs, rhs) \ + ((void)(((lhs) != (rhs)) || \ + (UT_ASSERT_MSG("%s (0x%llx) != %s (0x%llx)", #lhs, \ (unsigned long long)(lhs), #rhs, (unsigned long long)(rhs)), 0))) +/* assert two strings are equal at runtime */ +#define UT_ASSERTstreq_rt(__s1, __s2) \ + ((void)((__s1 == NULL && __s2 == NULL) || \ + (strcmp(__s1, __s2) == 0) || \ + (UT_ASSERT_MSG("%s: \"%s\" != %s", #__s1, __s1, __s2), 0))) + #if defined(__CHECKER__) #define UT_COMPILE_ERROR_ON(cond) #define UT_ASSERT_COMPILE_ERROR_ON(cond) @@ -255,11 +261,18 @@ ut_log_function(void *context, enum core_log_level level, const char *file_name, #define UT_ASSERTrange(ptr, start, size)\ ((void)(((uintptr_t)(ptr) >= (uintptr_t)(start) &&\ (uintptr_t)(ptr) < (uintptr_t)(start) + (uintptr_t)(size)) ||\ - (ut_fatal(__FILE__, __LINE__, __func__,\ - "assert failure: %s (%p) is outside range [%s (%p), %s (%p))", #ptr,\ + (UT_ASSERT_MSG("%s (%p) is outside range [%s (%p), %s (%p))", #ptr,\ (void *)(ptr), #start, (void *)(start), #start"+"#size,\ (void *)((uintptr_t)(start) + (uintptr_t)(size))), 0))) +/* assert strings are equal */ +#define UT_ASSERTstreq(__s1, __s2) \ + do { \ + if (__builtin_constant_p(__s1)) \ + UT_FATAL("UT_ASSERTstreq the first param must not be " \ + "const"); \ + UT_ASSERTstreq_rt(__s1, __s2); \ + } while (0) /* * memory allocation... */