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 <jhrozek@redhat.com>
Reviewed-by: Stephen Gallagher <sgallagh@redhat.com>
Reviewed-by: Simo Sorce <simo@redhat.com>

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