From fb0332565892bc10998ca98b567d4dde2213844d Mon Sep 17 00:00:00 2001 From: Nikolai Kondrashov Date: Thu, 10 Oct 2013 13:16:36 +0300 Subject: Move DEBUG macro body to debug_fn Move DEBUG macro body to the debug_fn function, adding "function" argument to the latter. Rename "debug_fn" in sssd_krb5_locator_plugin.c to "plugin_debug_fn" to remove conflict with the sssd debug_fn. Replace DEBUG_MSG macro usage with debug_fn function usage. Remove DEBUG_MSG macro along with tests. The above makes the total size of binaries drop by 20% for the standard Fedora build and by 44% for a build configured according to Debian packaging script. Reviewed-by: Jakub Hrozek Reviewed-by: Stephen Gallagher Reviewed-by: Simo Sorce --- src/krb5_plugin/sssd_krb5_locator_plugin.c | 4 +- src/tests/debug-tests.c | 299 +---------------------------- src/tools/selinux.c | 3 +- src/util/debug.c | 50 ++++- src/util/util.h | 78 +------- 5 files changed, 67 insertions(+), 367 deletions(-) diff --git a/src/krb5_plugin/sssd_krb5_locator_plugin.c b/src/krb5_plugin/sssd_krb5_locator_plugin.c index 725687ddc..a3a07d642 100644 --- a/src/krb5_plugin/sssd_krb5_locator_plugin.c +++ b/src/krb5_plugin/sssd_krb5_locator_plugin.c @@ -48,7 +48,7 @@ #define DEBUG_KEY "[sssd_krb5_locator] " #define PLUGIN_DEBUG(body) do { \ if (ctx->debug) { \ - debug_fn body; \ + plugin_debug_fn body; \ } \ } while(0) @@ -61,7 +61,7 @@ struct sssd_ctx { bool debug; }; -void debug_fn(const char *format, ...) +void plugin_debug_fn(const char *format, ...) { va_list ap; char *s = NULL; diff --git a/src/tests/debug-tests.c b/src/tests/debug-tests.c index f73f9bd7e..0902005af 100644 --- a/src/tests/debug-tests.c +++ b/src/tests/debug-tests.c @@ -179,7 +179,7 @@ START_TEST(test_debug_get_level_new_format) } END_TEST -int test_helper_debug_check_message(int level, int msgmode) +int test_helper_debug_check_message(int level) { TALLOC_CTX *ctx = talloc_new(NULL); char filename[24] = {'\0'}; @@ -221,11 +221,7 @@ int test_helper_debug_check_message(int level, int msgmode) goto done; } - if (msgmode == 0) { - DEBUG(level, ("%s", body)); - } else { - DEBUG_MSG(level, __FUNCTION__, "some error"); - } + DEBUG(level, ("%s", body)); ret = fseek(file, 0, SEEK_END); if (ret == -1) { @@ -329,7 +325,7 @@ done: return ret; } -int test_helper_debug_is_empty_message(int level, int msgmode) +int test_helper_debug_is_empty_message(int level) { char filename[24] = {'\0'}; int fd; @@ -362,11 +358,7 @@ int test_helper_debug_is_empty_message(int level, int msgmode) goto done; } - if (msgmode == 0) { - DEBUG(level, ("some error\n")); - } else { - DEBUG_MSG(level, __FUNCTION__, "some error"); - } + DEBUG(level, ("some error\n")); ret = fseek(file, 0, SEEK_END); if (ret == -1) { @@ -420,7 +412,7 @@ START_TEST(test_debug_is_set_single_no_timestamp) debug_level = levels[i]; errno = 0; - result = test_helper_debug_check_message(levels[i], 0); + result = test_helper_debug_check_message(levels[i]); if (result == DEBUG_TEST_ERROR) { error_msg = strerror(errno); @@ -462,7 +454,7 @@ START_TEST(test_debug_is_set_single_timestamp) debug_level = levels[i]; errno = 0; - result = test_helper_debug_check_message(levels[i], 0); + result = test_helper_debug_check_message(levels[i]); if (result == DEBUG_TEST_ERROR) { error_msg = strerror(errno); @@ -509,7 +501,7 @@ START_TEST(test_debug_is_set_single_timestamp_microseconds) debug_level = levels[i]; errno = 0; - result = test_helper_debug_check_message(levels[i], 0); + result = test_helper_debug_check_message(levels[i]); if (result == DEBUG_TEST_ERROR) { error_msg = strerror(errno); @@ -557,7 +549,7 @@ START_TEST(test_debug_is_notset_no_timestamp) debug_level = all_set & ~levels[i]; errno = 0; - result = test_helper_debug_is_empty_message(levels[i], 0); + result = test_helper_debug_is_empty_message(levels[i]); if (result == DEBUG_TEST_ERROR) { error_msg = strerror(errno); @@ -602,7 +594,7 @@ START_TEST(test_debug_is_notset_timestamp) debug_level = all_set & ~levels[i]; errno = 0; - result = test_helper_debug_is_empty_message(levels[i], 0); + result = test_helper_debug_is_empty_message(levels[i]); if (result == DEBUG_TEST_ERROR) { error_msg = strerror(errno); @@ -647,7 +639,7 @@ START_TEST(test_debug_is_notset_timestamp_microseconds) debug_level = all_set & ~levels[i]; errno = 0; - result = test_helper_debug_is_empty_message(levels[i], 0); + result = test_helper_debug_is_empty_message(levels[i]); if (result == DEBUG_TEST_ERROR) { error_msg = strerror(errno); @@ -664,271 +656,6 @@ START_TEST(test_debug_is_notset_timestamp_microseconds) } END_TEST -START_TEST(test_debug_msg_is_set_single_no_timestamp) -{ - int i; - int result; - int levels[] = { - SSSDBG_FATAL_FAILURE, - SSSDBG_CRIT_FAILURE, - SSSDBG_OP_FAILURE, - SSSDBG_MINOR_FAILURE, - SSSDBG_CONF_SETTINGS, - SSSDBG_FUNC_DATA, - SSSDBG_TRACE_FUNC, - SSSDBG_TRACE_LIBS, - SSSDBG_TRACE_INTERNAL, - SSSDBG_TRACE_ALL - }; - char *error_msg; - - debug_timestamps = 0; - debug_microseconds = 0; - debug_to_file = 1; - debug_prg_name = "sssd"; - - for (i = 0; i <= 9; i++) { - debug_level = levels[i]; - - errno = 0; - result = test_helper_debug_check_message(levels[i], 1); - - if (result == DEBUG_TEST_ERROR) { - error_msg = strerror(errno); - fail(error_msg); - } - - char *msg = NULL; - msg = talloc_asprintf(NULL, "Test of level %#.4x failed - message don't match", levels[i]); - fail_unless(result == EOK, msg); - talloc_free(msg); - } -} -END_TEST - -START_TEST(test_debug_msg_is_set_single_timestamp) -{ - int i; - int result; - int levels[] = { - SSSDBG_FATAL_FAILURE, - SSSDBG_CRIT_FAILURE, - SSSDBG_OP_FAILURE, - SSSDBG_MINOR_FAILURE, - SSSDBG_CONF_SETTINGS, - SSSDBG_FUNC_DATA, - SSSDBG_TRACE_FUNC, - SSSDBG_TRACE_LIBS, - SSSDBG_TRACE_INTERNAL, - SSSDBG_TRACE_ALL - }; - char *error_msg; - - debug_timestamps = 1; - debug_microseconds = 0; - debug_to_file = 1; - debug_prg_name = "sssd"; - - for (i = 0; i <= 9; i++) { - debug_level = levels[i]; - - errno = 0; - result = test_helper_debug_check_message(levels[i], 1); - - if (result == DEBUG_TEST_ERROR) { - error_msg = strerror(errno); - fail(error_msg); - } - - char *msg = NULL; - - msg = talloc_asprintf(NULL, "Test of level %#.4x failed - invalid timestamp", levels[i]); - fail_if(result == DEBUG_TEST_NOK_TS, msg); - talloc_free(msg); - - msg = talloc_asprintf(NULL, "Test of level %#.4x failed - message don't match", levels[i]); - fail_unless(result == EOK, msg); - talloc_free(msg); - } -} -END_TEST - -START_TEST(test_debug_msg_is_set_single_timestamp_microseconds) -{ - int i; - int result; - int levels[] = { - SSSDBG_FATAL_FAILURE, - SSSDBG_CRIT_FAILURE, - SSSDBG_OP_FAILURE, - SSSDBG_MINOR_FAILURE, - SSSDBG_CONF_SETTINGS, - SSSDBG_FUNC_DATA, - SSSDBG_TRACE_FUNC, - SSSDBG_TRACE_LIBS, - SSSDBG_TRACE_INTERNAL, - SSSDBG_TRACE_ALL - }; - char *error_msg; - - debug_timestamps = 1; - debug_microseconds = 1; - debug_to_file = 1; - debug_prg_name = "sssd"; - - for (i = 0; i <= 9; i++) { - debug_level = levels[i]; - - errno = 0; - result = test_helper_debug_check_message(levels[i], 1); - - if (result == DEBUG_TEST_ERROR) { - error_msg = strerror(errno); - fail(error_msg); - } - - char *msg = NULL; - - msg = talloc_asprintf(NULL, "Test of level %#.4x failed - invalid timestamp", levels[i]); - fail_if(result == DEBUG_TEST_NOK_TS, msg); - talloc_free(msg); - - msg = talloc_asprintf(NULL, "Test of level %#.4x failed - message don't match", levels[i]); - fail_unless(result == EOK, msg); - talloc_free(msg); - } -} -END_TEST - -START_TEST(test_debug_msg_is_notset_no_timestamp) -{ - int i; - int result; - int all_set = SSSDBG_MASK_ALL; - int levels[] = { - SSSDBG_FATAL_FAILURE, - SSSDBG_CRIT_FAILURE, - SSSDBG_OP_FAILURE, - SSSDBG_MINOR_FAILURE, - SSSDBG_CONF_SETTINGS, - SSSDBG_FUNC_DATA, - SSSDBG_TRACE_FUNC, - SSSDBG_TRACE_LIBS, - SSSDBG_TRACE_INTERNAL, - SSSDBG_TRACE_ALL - }; - char *error_msg; - - debug_timestamps = 0; - debug_microseconds = 0; - debug_to_file = 1; - debug_prg_name = "sssd"; - - for (i = 0; i <= 9; i++) { - debug_level = all_set & ~levels[i]; - - errno = 0; - result = test_helper_debug_is_empty_message(levels[i], 1); - - if (result == DEBUG_TEST_ERROR) { - error_msg = strerror(errno); - fail(error_msg); - } - - char *msg = NULL; - msg = talloc_asprintf(NULL, "Test of level %#.4x failed - message has been written", levels[i]); - fail_unless(result == EOK, msg); - talloc_free(msg); - } -} -END_TEST - -START_TEST(test_debug_msg_is_notset_timestamp) -{ - int i; - int result; - int all_set = SSSDBG_MASK_ALL; - int levels[] = { - SSSDBG_FATAL_FAILURE, - SSSDBG_CRIT_FAILURE, - SSSDBG_OP_FAILURE, - SSSDBG_MINOR_FAILURE, - SSSDBG_CONF_SETTINGS, - SSSDBG_FUNC_DATA, - SSSDBG_TRACE_FUNC, - SSSDBG_TRACE_LIBS, - SSSDBG_TRACE_INTERNAL, - SSSDBG_TRACE_ALL - }; - char *error_msg; - - debug_timestamps = 0; - debug_microseconds = 0; - debug_to_file = 1; - debug_prg_name = "sssd"; - - for (i = 0; i <= 9; i++) { - debug_level = all_set & ~levels[i]; - - errno = 0; - result = test_helper_debug_is_empty_message(levels[i], 1); - - if (result == DEBUG_TEST_ERROR) { - error_msg = strerror(errno); - fail(error_msg); - } - - char *msg = NULL; - msg = talloc_asprintf(NULL, "Test of level %#.4x failed - message has been written", levels[i]); - fail_unless(result == EOK, msg); - talloc_free(msg); - } -} -END_TEST - -START_TEST(test_debug_msg_is_notset_timestamp_microseconds) -{ - int i; - int result; - int all_set = SSSDBG_MASK_ALL; - int levels[] = { - SSSDBG_FATAL_FAILURE, - SSSDBG_CRIT_FAILURE, - SSSDBG_OP_FAILURE, - SSSDBG_MINOR_FAILURE, - SSSDBG_CONF_SETTINGS, - SSSDBG_FUNC_DATA, - SSSDBG_TRACE_FUNC, - SSSDBG_TRACE_LIBS, - SSSDBG_TRACE_INTERNAL, - SSSDBG_TRACE_ALL - }; - char *error_msg; - - debug_timestamps = 0; - debug_microseconds = 1; - debug_to_file = 1; - debug_prg_name = "sssd"; - - for (i = 0; i <= 9; i++) { - debug_level = all_set & ~levels[i]; - - errno = 0; - result = test_helper_debug_is_empty_message(levels[i], 1); - - if (result == DEBUG_TEST_ERROR) { - error_msg = strerror(errno); - fail(error_msg); - } - - char *msg = NULL; - msg = talloc_asprintf(NULL, "Test of level %#.4x failed - message has been written", levels[i]); - fail_unless(result == EOK, msg); - talloc_free(msg); - } -} -END_TEST - START_TEST(test_debug_is_set_true) { int i; @@ -1004,12 +731,6 @@ Suite *debug_suite(void) tcase_add_test(tc_debug, test_debug_is_notset_no_timestamp); tcase_add_test(tc_debug, test_debug_is_notset_timestamp); tcase_add_test(tc_debug, test_debug_is_notset_timestamp_microseconds); - tcase_add_test(tc_debug, test_debug_msg_is_set_single_no_timestamp); - tcase_add_test(tc_debug, test_debug_msg_is_set_single_timestamp); - tcase_add_test(tc_debug, test_debug_msg_is_set_single_timestamp_microseconds); - tcase_add_test(tc_debug, test_debug_msg_is_notset_no_timestamp); - tcase_add_test(tc_debug, test_debug_msg_is_notset_timestamp); - tcase_add_test(tc_debug, test_debug_msg_is_notset_timestamp_microseconds); tcase_add_test(tc_debug, test_debug_is_set_true); tcase_add_test(tc_debug, test_debug_is_set_false); tcase_set_timeout(tc_debug, 60); diff --git a/src/tools/selinux.c b/src/tools/selinux.c index 4f0c8c711..4555a486f 100644 --- a/src/tools/selinux.c +++ b/src/tools/selinux.c @@ -121,7 +121,8 @@ static void sss_semanage_error_callback(void *varg, return; } - DEBUG_MSG(level, "libsemanage", message); + if (DEBUG_IS_SET(level)) + debug_fn("libsemanage", level, "%s\n", message); free(message); } diff --git a/src/util/debug.c b/src/util/debug.c index 324f0daeb..91a030f2c 100644 --- a/src/util/debug.c +++ b/src/util/debug.c @@ -104,18 +104,59 @@ int debug_convert_old_level(int old_level) return new_level; } -void debug_fn(const char *format, ...) +static void debug_vprintf(const char *format, va_list ap) +{ + vfprintf(debug_file ? debug_file : stderr, format, ap); + fflush(debug_file ? debug_file : stderr); +} + +static void debug_printf(const char *format, ...) + SSS_ATTRIBUTE_PRINTF(1, 2); + +static void debug_printf(const char *format, ...) { va_list ap; va_start(ap, format); - vfprintf(debug_file ? debug_file : stderr, format, ap); - fflush(debug_file ? debug_file : stderr); + debug_vprintf(format, ap); va_end(ap); } +void debug_fn(const char *function, int newlevel, const char *format, ...) +{ + va_list ap; + if (debug_timestamps) { + struct timeval tv; + struct tm *tm; + char datetime[20]; + int year; + gettimeofday(&tv, NULL); + tm = localtime(&tv.tv_sec); + year = tm->tm_year + 1900; + /* get date time without year */ + memcpy(datetime, ctime(&tv.tv_sec), 19); + datetime[19] = '\0'; + if (debug_microseconds) { + debug_printf("(%s:%.6ld %d) [%s] [%s] (%#.4x): ", + datetime, tv.tv_usec, + year, debug_prg_name, + function, newlevel); + } else { + debug_printf("(%s %d) [%s] [%s] (%#.4x): ", + datetime, year, + debug_prg_name, function, newlevel); + } + } else { + debug_printf("[%s] [%s] (%#.4x): ", + debug_prg_name, function, newlevel); + } + va_start(ap, format); + debug_vprintf(format, ap); + va_end(ap); +} + int debug_get_level(int old_level) { if ((old_level != 0) && !(old_level & 0x000F)) @@ -168,7 +209,8 @@ void ldb_debug_messages(void *context, enum ldb_debug_level level, return; } - DEBUG_MSG(loglevel, "ldb", message); + if (DEBUG_IS_SET(loglevel)) + debug_fn("ldb", loglevel, "%s\n", message); free(message); } diff --git a/src/util/util.h b/src/util/util.h index 04fe0cefb..7650e3e9a 100644 --- a/src/util/util.h +++ b/src/util/util.h @@ -68,7 +68,8 @@ extern int debug_timestamps; extern int debug_microseconds; extern int debug_to_file; extern const char *debug_log_file; -void debug_fn(const char *format, ...) SSS_ATTRIBUTE_PRINTF(1, 2); +void debug_fn(const char *function, int newlevel, const char *format, ...) + SSS_ATTRIBUTE_PRINTF(3, 4); int debug_get_level(int old_level); int debug_convert_old_level(int old_level); errno_t set_debug_file_from_fd(const int fd); @@ -108,6 +109,8 @@ errno_t set_debug_file_from_fd(const int fd); {"debug-microseconds", 0, POPT_ARG_INT, &debug_microseconds, 0, \ _("Show timestamps with microseconds"), NULL}, +#define DEBUG_UNWRAP(...) __VA_ARGS__ + /** \def DEBUG(level, body) \brief macro to generate debug messages @@ -125,76 +128,9 @@ errno_t set_debug_file_from_fd(const int fd); */ #define DEBUG(level, body) do { \ int __debug_macro_newlevel = debug_get_level(level); \ - if (DEBUG_IS_SET(__debug_macro_newlevel)) { \ - if (debug_timestamps) { \ - struct timeval __debug_macro_tv; \ - struct tm *__debug_macro_tm; \ - char __debug_macro_datetime[20]; \ - int __debug_macro_year; \ - gettimeofday(&__debug_macro_tv, NULL); \ - __debug_macro_tm = localtime(&__debug_macro_tv.tv_sec); \ - __debug_macro_year = __debug_macro_tm->tm_year + 1900; \ - /* get date time without year */ \ - memcpy(__debug_macro_datetime, ctime(&__debug_macro_tv.tv_sec), 19); \ - __debug_macro_datetime[19] = '\0'; \ - if (debug_microseconds) { \ - debug_fn("(%s:%.6ld %d) [%s] [%s] (%#.4x): ", \ - __debug_macro_datetime, __debug_macro_tv.tv_usec, \ - __debug_macro_year, debug_prg_name, \ - __FUNCTION__, __debug_macro_newlevel); \ - } else { \ - debug_fn("(%s %d) [%s] [%s] (%#.4x): ", \ - __debug_macro_datetime, __debug_macro_year, \ - debug_prg_name, __FUNCTION__, __debug_macro_newlevel); \ - } \ - } else { \ - debug_fn("[%s] [%s] (%#.4x): ", \ - debug_prg_name, __FUNCTION__, __debug_macro_newlevel); \ - } \ - debug_fn body; \ - } \ -} while(0) - -/** \def DEBUG_MSG(level, function, message) - \brief macro to generate debug messages with message from variable - - \param level the debug level, please use one of the SSSDBG_* macros - - \param function name of the function where DEBUG_MSG is called - - \param message message to be send (should not end with \n) -*/ -#define DEBUG_MSG(level, function, message) do { \ - int __debug_macro_newlevel = debug_get_level(level); \ - if (DEBUG_IS_SET(__debug_macro_newlevel)) { \ - if (debug_timestamps) { \ - struct timeval __debug_macro_tv; \ - struct tm *__debug_macro_tm; \ - char __debug_macro_datetime[20]; \ - int __debug_macro_year; \ - gettimeofday(&__debug_macro_tv, NULL); \ - __debug_macro_tm = localtime(&__debug_macro_tv.tv_sec); \ - __debug_macro_year = __debug_macro_tm->tm_year + 1900; \ - /* get date time without year */ \ - memcpy(__debug_macro_datetime, ctime(&__debug_macro_tv.tv_sec), 19); \ - __debug_macro_datetime[19] = '\0'; \ - if (debug_microseconds) { \ - debug_fn("(%s:%.6ld %d) [%s] [%s] (%#.4x): %s\n", \ - __debug_macro_datetime, __debug_macro_tv.tv_usec, \ - __debug_macro_year, debug_prg_name, \ - function, __debug_macro_newlevel, message); \ - } else { \ - debug_fn("(%s %d) [%s] [%s] (%#.4x): %s\n", \ - __debug_macro_datetime, __debug_macro_year, \ - debug_prg_name, function, __debug_macro_newlevel, \ - message); \ - } \ - } else { \ - debug_fn("[%s] [%s] (%#.4x): %s\n", \ - debug_prg_name, function, __debug_macro_newlevel, message); \ - } \ - } \ -} while(0) + if (DEBUG_IS_SET(__debug_macro_newlevel)) \ + debug_fn(__FUNCTION__, __debug_macro_newlevel, DEBUG_UNWRAP body); \ +} while (0) /** \def DEBUG_IS_SET(level) \brief checks whether level (must be in new format) is set in debug_level -- cgit