From 1a7529bf5f867b43e0475f7f9ac0cd8671fb16f1 Mon Sep 17 00:00:00 2001 From: Pavel Březina Date: Mon, 29 Aug 2011 10:32:03 +0200 Subject: DEBUG timestamps offer higher precision https://fedorahosted.org/sssd/ticket/956 Added: --debug-microseconds=0/1 Added: debug_microseconds to sssd.conf --- src/confdb/confdb.h | 1 + src/monitor/monitor.c | 28 ++++++++++++++++-- src/providers/child_common.c | 21 +++++++++++--- src/providers/krb5/krb5_child.c | 2 ++ src/providers/ldap/ldap_child.c | 2 ++ src/providers/proxy/proxy_auth.c | 5 ++-- src/util/debug.c | 1 + src/util/server.c | 16 +++++++++++ src/util/util.h | 61 +++++++++++++++++++++++++++++++--------- 9 files changed, 116 insertions(+), 21 deletions(-) diff --git a/src/confdb/confdb.h b/src/confdb/confdb.h index 4d615761..266e4d27 100644 --- a/src/confdb/confdb.h +++ b/src/confdb/confdb.h @@ -51,6 +51,7 @@ #define CONFDB_SERVICE_COMMAND "command" #define CONFDB_SERVICE_DEBUG_LEVEL "debug_level" #define CONFDB_SERVICE_DEBUG_TIMESTAMPS "debug_timestamps" +#define CONFDB_SERVICE_DEBUG_MICROSECONDS "debug_microseconds" #define CONFDB_SERVICE_DEBUG_TO_FILES "debug_to_files" #define CONFDB_SERVICE_TIMEOUT "timeout" #define CONFDB_SERVICE_RECON_RETRIES "reconnection_retries" diff --git a/src/monitor/monitor.c b/src/monitor/monitor.c index 4cd1e99d..799b7c69 100644 --- a/src/monitor/monitor.c +++ b/src/monitor/monitor.c @@ -62,6 +62,7 @@ int cmdline_debug_level; int cmdline_debug_timestamps; +int cmdline_debug_microseconds; struct svc_spy; @@ -975,6 +976,17 @@ static int get_service_config(struct mt_ctx *ctx, const char *name, } } + if (cmdline_debug_microseconds != SSSDBG_MICROSECONDS_UNRESOLVED) { + svc->command = talloc_asprintf_append( + svc->command, " --debug-microseconds=%d", + cmdline_debug_microseconds + ); + if (!svc->command) { + talloc_free(svc); + return ENOMEM; + } + } + if (debug_to_file) { svc->command = talloc_strdup_append( svc->command, " --debug-to-files" @@ -1130,6 +1142,17 @@ static int get_provider_config(struct mt_ctx *ctx, const char *name, } } + if (cmdline_debug_microseconds != SSSDBG_MICROSECONDS_UNRESOLVED) { + svc->command = talloc_asprintf_append( + svc->command, " --debug-microseconds=%d", + cmdline_debug_microseconds + ); + if (!svc->command) { + talloc_free(svc); + return ENOMEM; + } + } + if (debug_to_file) { svc->command = talloc_strdup_append( svc->command, " --debug-to-files" @@ -2390,11 +2413,12 @@ int main(int argc, const char *argv[]) CONVERT_AND_SET_DEBUG_LEVEL(debug_level); - /* If the level or timestamps was passed at the command-line, we want - * to save it and pass it to the children later. + /* If the level, timestamps or microseconds was passed at the command-line, + * we want to save it and pass it to the children later. */ cmdline_debug_level = debug_level; cmdline_debug_timestamps = debug_timestamps; + cmdline_debug_microseconds = debug_microseconds; if (opt_daemon && opt_interactive) { fprintf(stderr, "Option -i|--interactive is not allowed together with -D|--daemon\n"); diff --git a/src/providers/child_common.c b/src/providers/child_common.c index cde310c3..5920ebc7 100644 --- a/src/providers/child_common.c +++ b/src/providers/child_common.c @@ -378,19 +378,25 @@ static errno_t prepare_child_argv(TALLOC_CTX *mem_ctx, const char *binary, char ***_argv) { - uint_t argc = 4; /* program name, debug_level, debug_timestamps and NULL */ + /* + * program name, debug_level, debug_timestamps, + * debug_microseconds and NULL + */ + uint_t argc = 5; char ** argv; errno_t ret = EINVAL; /* Save the current state in case an interrupt changes it */ bool child_debug_to_file = debug_to_file; bool child_debug_timestamps = debug_timestamps; + bool child_debug_microseconds = debug_microseconds; if (child_debug_to_file) argc++; - /* program name, debug_level, - * debug_to_file, debug_timestamps - * and NULL */ + /* + * program name, debug_level, debug_to_file, debug_timestamps, + * debug_microseconds and NULL + */ argv = talloc_array(mem_ctx, char *, argc); if (argv == NULL) { DEBUG(1, ("talloc_array failed.\n")); @@ -422,6 +428,13 @@ static errno_t prepare_child_argv(TALLOC_CTX *mem_ctx, goto fail; } + argv[--argc] = talloc_asprintf(argv, "--debug-microseconds=%d", + child_debug_microseconds); + if (argv[argc] == NULL) { + ret = ENOMEM; + goto fail; + } + argv[--argc] = talloc_strdup(argv, binary); if (argv[argc] == NULL) { ret = ENOMEM; diff --git a/src/providers/krb5/krb5_child.c b/src/providers/krb5/krb5_child.c index fc678efa..7f6f9367 100644 --- a/src/providers/krb5/krb5_child.c +++ b/src/providers/krb5/krb5_child.c @@ -1554,6 +1554,8 @@ int main(int argc, const char *argv[]) _("Debug level"), NULL}, {"debug-timestamps", 0, POPT_ARG_INT, &debug_timestamps, 0, _("Add debug timestamps"), NULL}, + {"debug-microseconds", 0, POPT_ARG_INT, &debug_microseconds, 0, + _("Show timestamps with microseconds"), NULL}, {"debug-fd", 0, POPT_ARG_INT, &debug_fd, 0, _("An open file descriptor for the debug logs"), NULL}, POPT_TABLEEND diff --git a/src/providers/ldap/ldap_child.c b/src/providers/ldap/ldap_child.c index 368c2012..b0051fa9 100644 --- a/src/providers/ldap/ldap_child.c +++ b/src/providers/ldap/ldap_child.c @@ -360,6 +360,8 @@ int main(int argc, const char *argv[]) _("Debug level"), NULL}, {"debug-timestamps", 0, POPT_ARG_INT, &debug_timestamps, 0, _("Add debug timestamps"), NULL}, + {"debug-microseconds", 0, POPT_ARG_INT, &debug_microseconds, 0, + _("Show timestamps with microseconds"), NULL}, {"debug-fd", 0, POPT_ARG_INT, &debug_fd, 0, _("An open file descriptor for the debug logs"), NULL}, POPT_TABLEEND diff --git a/src/providers/proxy/proxy_auth.c b/src/providers/proxy/proxy_auth.c index 81ae896b..cd291782 100644 --- a/src/providers/proxy/proxy_auth.c +++ b/src/providers/proxy/proxy_auth.c @@ -240,9 +240,10 @@ static struct tevent_req *proxy_child_init_send(TALLOC_CTX *mem_ctx, state->child_ctx = child_ctx; state->command = talloc_asprintf(req, - "%s/proxy_child -d %#.4x --debug-timestamps=%d%s --domain %s --id %d", + "%s/proxy_child -d %#.4x --debug-timestamps=%d " + "--debug-microseconds=%d%s --domain %s --id %d", SSSD_LIBEXEC_PATH, debug_level, debug_timestamps, - (debug_to_file ? " --debug-to-files" : ""), + debug_microseconds, (debug_to_file ? " --debug-to-files" : ""), auth_ctx->be->domain->name, child_ctx->id); if (state->command == NULL) { diff --git a/src/util/debug.c b/src/util/debug.c index 3a1b7ca2..7816bc41 100644 --- a/src/util/debug.c +++ b/src/util/debug.c @@ -35,6 +35,7 @@ const char *debug_prg_name = "sssd"; int debug_level = SSSDBG_UNRESOLVED; int debug_timestamps = SSSDBG_TIMESTAMP_UNRESOLVED; +int debug_microseconds = SSSDBG_MICROSECONDS_UNRESOLVED; int debug_to_file = 0; const char *debug_log_file = "sssd"; FILE *debug_file = NULL; diff --git a/src/util/server.c b/src/util/server.c index 42fd9360..0c9501b1 100644 --- a/src/util/server.c +++ b/src/util/server.c @@ -382,6 +382,7 @@ int server_setup(const char *name, int flags, int ret = EOK; bool dt; bool dl; + bool dm; struct tevent_signal *tes; struct logrotate_ctx *lctx; @@ -489,6 +490,21 @@ int server_setup(const char *name, int flags, else debug_timestamps = 0; } + /* same for debug microseconds */ + if (debug_microseconds == SSSDBG_MICROSECONDS_UNRESOLVED) { + ret = confdb_get_bool(ctx->confdb_ctx, ctx, conf_entry, + CONFDB_SERVICE_DEBUG_MICROSECONDS, + SSSDBG_MICROSECONDS_DEFAULT, + &dm); + if (ret != EOK) { + DEBUG(0, ("Error reading from confdb (%d) [%s]\n", + ret, strerror(ret))); + return ret; + } + if (dm) debug_microseconds = 1; + else debug_microseconds = 0; + } + /* same for debug to file */ dl = (debug_to_file != 0); ret = confdb_get_bool(ctx->confdb_ctx, ctx, conf_entry, diff --git a/src/util/util.h b/src/util/util.h index c37cab8a..118d70c5 100644 --- a/src/util/util.h +++ b/src/util/util.h @@ -54,6 +54,7 @@ typedef int errno_t; extern const char *debug_prg_name; extern int debug_level; 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, ...); @@ -80,13 +81,18 @@ errno_t set_debug_file_from_fd(const int fd); #define SSSDBG_TIMESTAMP_UNRESOLVED -1 #define SSSDBG_TIMESTAMP_DEFAULT 1 +#define SSSDBG_MICROSECONDS_UNRESOLVED -1 +#define SSSDBG_MICROSECONDS_DEFAULT 0 + #define SSSD_DEBUG_OPTS \ {"debug-level", 'd', POPT_ARG_INT, &debug_level, 0, \ _("Debug level"), NULL}, \ {"debug-to-files", 'f', POPT_ARG_NONE, &debug_to_file, 0, \ _("Send the debug output to files instead of stderr"), NULL }, \ {"debug-timestamps", 0, POPT_ARG_INT, &debug_timestamps, 0, \ - _("Add debug timestamps"), NULL}, + _("Add debug timestamps"), NULL}, \ + {"debug-microseconds", 0, POPT_ARG_INT, &debug_microseconds, 0, \ + _("Show timestamps with microseconds"), NULL}, /** \def DEBUG(level, body) \brief macro to generate debug messages @@ -107,12 +113,26 @@ errno_t set_debug_file_from_fd(const int fd); int __debug_macro_newlevel = debug_get_level(level); \ if (DEBUG_IS_SET(__debug_macro_newlevel)) { \ if (debug_timestamps) { \ - time_t rightnow = time(NULL); \ - char stamp[25]; \ - memcpy(stamp, ctime(&rightnow), 24); \ - stamp[24] = '\0'; \ - debug_fn("(%s) [%s] [%s] (%#.4x): ", \ - stamp, debug_prg_name, __FUNCTION__, __debug_macro_newlevel); \ + 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:%.6d %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); \ @@ -134,12 +154,27 @@ errno_t set_debug_file_from_fd(const int fd); int __debug_macro_newlevel = debug_get_level(level); \ if (DEBUG_IS_SET(__debug_macro_newlevel)) { \ if (debug_timestamps) { \ - time_t rightnow = time(NULL); \ - char stamp[25]; \ - memcpy(stamp, ctime(&rightnow), 24); \ - stamp[24] = '\0'; \ - debug_fn("(%s) [%s] [%s] (%#.4x): %s\n", \ - stamp, debug_prg_name, function, __debug_macro_newlevel, message); \ + 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:%.6d %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); \ -- cgit