URL: https://github.com/SSSD/sssd/pull/5585 Author: alexey-tikhonov Title: #5585: Poor man's backtrace. Action: synchronized
To pull the PR as Git branch: git remote add ghsssd https://github.com/SSSD/sssd git fetch ghsssd pull/5585/head:pr5585 git checkout pr5585
From b33deaa562b80a68462b9443d4eed51a1fc92d60 Mon Sep 17 00:00:00 2001 From: Alexey Tikhonov <[email protected]> Date: Fri, 19 Mar 2021 20:38:58 +0100 Subject: [PATCH 1/9] DEBUG: got rid of most explicit DEBUG_IS_SET checks as a preliminary step for "logs backtrace" feature --- src/db/sysdb.c | 6 ++---- src/p11_child/p11_child_openssl.c | 8 +++----- src/providers/data_provider_fo.c | 2 +- src/providers/files/files_certmap.c | 9 +++------ src/providers/ipa/ipa_access.c | 11 ++++------- src/providers/ipa/ipa_s2n_exop.c | 26 ++++++++++---------------- src/providers/krb5/krb5_child.c | 18 +++++++----------- src/providers/ldap/sdap_async.c | 16 ++++------------ src/providers/ldap/sdap_certmap.c | 10 ++++------ src/providers/ldap/sdap_fd_events.c | 10 ++++------ src/providers/proxy/proxy_id.c | 22 ++++++++++------------ src/responder/pam/pamsrv_p11.c | 10 ++++------ src/responder/ssh/ssh_cmd.c | 10 ++++------ src/sbus/connection/sbus_watch.c | 15 +++++++-------- src/util/debug.h | 23 ++++++++++++++--------- src/util/sss_pam_data.h | 2 +- src/util/sss_semanage.c | 6 ++---- src/util/tev_curl.c | 16 +++++++--------- 18 files changed, 91 insertions(+), 129 deletions(-) diff --git a/src/db/sysdb.c b/src/db/sysdb.c index 6001c49cb2..3fe0ebf6c2 100644 --- a/src/db/sysdb.c +++ b/src/db/sysdb.c @@ -2134,10 +2134,8 @@ void ldb_debug_messages(void *context, enum ldb_debug_level level, break; } - if (DEBUG_IS_SET(loglevel)) { - sss_vdebug_fn(__FILE__, __LINE__, "ldb", loglevel, APPEND_LINE_FEED, - fmt, ap); - } + sss_vdebug_fn(__FILE__, __LINE__, "ldb", loglevel, APPEND_LINE_FEED, + fmt, ap); } struct sss_domain_info *find_domain_by_msg(struct sss_domain_info *dom, diff --git a/src/p11_child/p11_child_openssl.c b/src/p11_child/p11_child_openssl.c index cee44df51c..78c05f5cb3 100644 --- a/src/p11_child/p11_child_openssl.c +++ b/src/p11_child/p11_child_openssl.c @@ -1335,11 +1335,9 @@ static CK_RV get_preferred_rsa_mechanism(TALLOC_CTX *mem_ctx, if (mechanism_list != NULL) { rv = module->C_GetMechanismList(slot_id, mechanism_list, &count); if (rv == CKR_OK) { - if (DEBUG_IS_SET(SSSDBG_TRACE_ALL)) { - for (m = 0; m < count; m++) { - DEBUG(SSSDBG_TRACE_ALL, "Found mechanism [%lu].\n", - mechanism_list[m]); - } + for (m = 0; m < count; m++) { + DEBUG(SSSDBG_TRACE_ALL, "Found mechanism [%lu].\n", + mechanism_list[m]); } for (c = 0; prefs[c].mech != 0; c++) { for (m = 0; m < count; m++) { diff --git a/src/providers/data_provider_fo.c b/src/providers/data_provider_fo.c index 0dfbb04b0f..639548a3db 100644 --- a/src/providers/data_provider_fo.c +++ b/src/providers/data_provider_fo.c @@ -645,7 +645,7 @@ errno_t be_resolve_server_process(struct tevent_req *subreq, return ENOENT; } - if (DEBUG_IS_SET(SSSDBG_FUNC_DATA) && fo_get_server_name(state->srv)) { + if (fo_get_server_name(state->srv)) { struct resolv_hostent *srvaddr; char ipaddr[128]; srvaddr = fo_get_server_hostent(state->srv); diff --git a/src/providers/files/files_certmap.c b/src/providers/files/files_certmap.c index 7d90a1fecf..665279f6f2 100644 --- a/src/providers/files/files_certmap.c +++ b/src/providers/files/files_certmap.c @@ -39,12 +39,9 @@ static void ext_debug(void *private, const char *file, long line, level = data->level; } - if (DEBUG_IS_SET(level)) { - va_start(ap, format); - sss_vdebug_fn(file, line, function, level, APPEND_LINE_FEED, - format, ap); - va_end(ap); - } + va_start(ap, format); + sss_vdebug_fn(file, line, function, level, APPEND_LINE_FEED, format, ap); + va_end(ap); } errno_t files_init_certmap(TALLOC_CTX *mem_ctx, struct files_id_ctx *id_ctx) diff --git a/src/providers/ipa/ipa_access.c b/src/providers/ipa/ipa_access.c index 4a6727c978..9b9cdf59f8 100644 --- a/src/providers/ipa/ipa_access.c +++ b/src/providers/ipa/ipa_access.c @@ -41,6 +41,7 @@ void hbac_debug_messages(const char *file, int line, const char *fmt, ...) { int loglevel; + va_list ap; switch(level) { case HBAC_DBG_FATAL: @@ -63,13 +64,9 @@ void hbac_debug_messages(const char *file, int line, break; } - if (DEBUG_IS_SET(loglevel)) { - va_list ap; - - va_start(ap, fmt); - sss_vdebug_fn(file, line, function, loglevel, 0, fmt, ap); - va_end(ap); - } + va_start(ap, fmt); + sss_vdebug_fn(file, line, function, loglevel, 0, fmt, ap); + va_end(ap); } enum hbac_result { diff --git a/src/providers/ipa/ipa_s2n_exop.c b/src/providers/ipa/ipa_s2n_exop.c index 08b1113fa0..b0baf0e67c 100644 --- a/src/providers/ipa/ipa_s2n_exop.c +++ b/src/providers/ipa/ipa_s2n_exop.c @@ -1658,14 +1658,12 @@ struct tevent_req *ipa_s2n_get_acct_info_send(TALLOC_CTX *mem_ctx, goto fail; } - if (DEBUG_IS_SET(SSSDBG_TRACE_FUNC)) { - input = ipa_s2n_reqinp2str(state, req_input); - DEBUG(SSSDBG_TRACE_FUNC, - "Sending request_type: [%s] for trust user [%s] to IPA server\n", - ipa_s2n_reqtype2str(state->request_type), - input); - talloc_zfree(input); - } + input = ipa_s2n_reqinp2str(state, req_input); + DEBUG(SSSDBG_TRACE_FUNC, + "Sending request_type: [%s] for trust user [%s] to IPA server\n", + ipa_s2n_reqtype2str(state->request_type), + input); + talloc_zfree(input); subreq = ipa_s2n_exop_send(state, state->ev, state->sh, state->protocol, state->exop_timeout, bv_req); @@ -2085,15 +2083,11 @@ static void ipa_s2n_get_user_done(struct tevent_req *subreq) if (attrs->response_type == RESP_USER_GROUPLIST) { - if (DEBUG_IS_SET(SSSDBG_TRACE_FUNC)) { - size_t c; + DEBUG(SSSDBG_TRACE_FUNC, "Received [%zu] groups in group list " + "from IPA Server\n", attrs->ngroups); - DEBUG(SSSDBG_TRACE_FUNC, "Received [%zu] groups in group list " - "from IPA Server\n", attrs->ngroups); - - for (c = 0; c < attrs->ngroups; c++) { - DEBUG(SSSDBG_TRACE_FUNC, "[%s].\n", attrs->groups[c]); - } + for (size_t c = 0; c < attrs->ngroups; c++) { + DEBUG(SSSDBG_TRACE_FUNC, "[%s].\n", attrs->groups[c]); } diff --git a/src/providers/krb5/krb5_child.c b/src/providers/krb5/krb5_child.c index 877d0b293a..fbd0555190 100644 --- a/src/providers/krb5/krb5_child.c +++ b/src/providers/krb5/krb5_child.c @@ -696,12 +696,10 @@ static krb5_error_code answer_pkinit(krb5_context ctx, goto done; } - if (DEBUG_IS_SET(SSSDBG_TRACE_ALL)) { - for (c = 0; chl->identities[c] != NULL; c++) { - DEBUG(SSSDBG_TRACE_ALL, "[%zu] Identity [%s] flags [%"PRId32"].\n", - c, chl->identities[c]->identity, - chl->identities[c]->token_flags); - } + for (c = 0; chl->identities[c] != NULL; c++) { + DEBUG(SSSDBG_TRACE_ALL, "[%zu] Identity [%s] flags [%"PRId32"].\n", + c, chl->identities[c]->identity, + chl->identities[c]->token_flags); } DEBUG(SSSDBG_TRACE_ALL, "Setting pkinit_prompting.\n"); @@ -847,11 +845,9 @@ static krb5_error_code sss_krb5_prompter(krb5_context context, void *data, name, banner, num_prompts); if (num_prompts != 0) { - if (DEBUG_IS_SET(SSSDBG_TRACE_ALL)) { - for (c = 0; c < num_prompts; c++) { - DEBUG(SSSDBG_TRACE_ALL, "Prompt [%zu][%s].\n", c, - prompts[c].prompt); - } + for (c = 0; c < num_prompts; c++) { + DEBUG(SSSDBG_TRACE_ALL, "Prompt [%zu][%s].\n", c, + prompts[c].prompt); } DEBUG(SSSDBG_FUNC_DATA, "Prompter interface isn't used for password prompts by SSSD.\n"); diff --git a/src/providers/ldap/sdap_async.c b/src/providers/ldap/sdap_async.c index cc77fb249d..6632abeb15 100644 --- a/src/providers/ldap/sdap_async.c +++ b/src/providers/ldap/sdap_async.c @@ -1247,10 +1247,6 @@ static void sdap_print_server(struct sdap_handle *sh) char ip[NI_MAXHOST]; int port; - if (!DEBUG_IS_SET(SSSDBG_TRACE_INTERNAL)) { - return; - } - ret = get_fd_from_ldap(sh->ldap, &fd); if (ret != EOK) { DEBUG(SSSDBG_MINOR_FAILURE, "cannot get sdap fd\n"); @@ -1470,14 +1466,10 @@ static errno_t sdap_get_generic_ext_step(struct tevent_req *req) "calling ldap_search_ext with [%s][%s].\n", state->filter ? state->filter : "no filter", state->search_base); - if (DEBUG_IS_SET(SSSDBG_TRACE_LIBS)) { - int i; - - if (state->attrs) { - for (i = 0; state->attrs[i]; i++) { - DEBUG(SSSDBG_TRACE_LIBS, - "Requesting attrs: [%s]\n", state->attrs[i]); - } + if (state->attrs) { + for (int i = 0; state->attrs[i]; i++) { + DEBUG(SSSDBG_TRACE_LIBS, + "Requesting attrs: [%s]\n", state->attrs[i]); } } diff --git a/src/providers/ldap/sdap_certmap.c b/src/providers/ldap/sdap_certmap.c index fcf88a9c69..e32895cf93 100644 --- a/src/providers/ldap/sdap_certmap.c +++ b/src/providers/ldap/sdap_certmap.c @@ -44,12 +44,10 @@ static void ext_debug(void *private, const char *file, long line, level = data->level; } - if (DEBUG_IS_SET(level)) { - va_start(ap, format); - sss_vdebug_fn(file, line, function, level, APPEND_LINE_FEED, - format, ap); - va_end(ap); - } + va_start(ap, format); + sss_vdebug_fn(file, line, function, level, APPEND_LINE_FEED, + format, ap); + va_end(ap); } struct sss_certmap_ctx *sdap_get_sss_certmap(struct sdap_certmap_ctx *ctx) diff --git a/src/providers/ldap/sdap_fd_events.c b/src/providers/ldap/sdap_fd_events.c index 96b8aa62e9..d3bcd55e29 100644 --- a/src/providers/ldap/sdap_fd_events.c +++ b/src/providers/ldap/sdap_fd_events.c @@ -128,12 +128,10 @@ static int sdap_ldap_connect_callback_add(LDAP *ld, Sockbuf *sb, } } - if (DEBUG_IS_SET(SSSDBG_TRACE_LIBS)) { - char *uri = ldap_url_desc2str(srv); - DEBUG(SSSDBG_TRACE_LIBS, "New LDAP connection to [%s] with fd [%d].\n", - uri, ber_fd); - free(uri); - } + char *uri = ldap_url_desc2str(srv); + DEBUG(SSSDBG_TRACE_LIBS, "New LDAP connection to [%s] with fd [%d].\n", + uri, ber_fd); + free(uri); fd_event_item = talloc_zero(cb_data, struct fd_event_item); if (fd_event_item == NULL) { diff --git a/src/providers/proxy/proxy_id.c b/src/providers/proxy/proxy_id.c index f363860891..25daea585d 100644 --- a/src/providers/proxy/proxy_id.c +++ b/src/providers/proxy/proxy_id.c @@ -565,19 +565,17 @@ static int enum_users(TALLOC_CTX *mem_ctx, /* =Save-group-utilities=================================================*/ #define DEBUG_GR_MEM(level, grp) \ do { \ - if (DEBUG_IS_SET(level)) { \ - if (!grp->gr_mem || !grp->gr_mem[0]) { \ - DEBUG(level, "Group %s has no members!\n", \ - grp->gr_name); \ - } else { \ - int i = 0; \ - while (grp->gr_mem[i]) { \ - /* count */ \ - i++; \ - } \ - DEBUG(level, "Group %s has %d members!\n", \ - grp->gr_name, i); \ + if (!grp->gr_mem || !grp->gr_mem[0]) { \ + DEBUG(level, "Group %s has no members!\n", \ + grp->gr_name); \ + } else { \ + int i = 0; \ + while (grp->gr_mem[i]) { \ + /* count */ \ + i++; \ } \ + DEBUG(level, "Group %s has %d members!\n", \ + grp->gr_name, i); \ } \ } while(0) diff --git a/src/responder/pam/pamsrv_p11.c b/src/responder/pam/pamsrv_p11.c index bf285c264f..3b21332db9 100644 --- a/src/responder/pam/pamsrv_p11.c +++ b/src/responder/pam/pamsrv_p11.c @@ -132,12 +132,10 @@ static void ext_debug(void *private, const char *file, long line, level = data->level; } - if (DEBUG_IS_SET(level)) { - va_start(ap, format); - sss_vdebug_fn(file, line, function, level, APPEND_LINE_FEED, - format, ap); - va_end(ap); - } + va_start(ap, format); + sss_vdebug_fn(file, line, function, level, APPEND_LINE_FEED, + format, ap); + va_end(ap); } errno_t p11_refresh_certmap_ctx(struct pam_ctx *pctx, diff --git a/src/responder/ssh/ssh_cmd.c b/src/responder/ssh/ssh_cmd.c index a593c904f6..45ab57be59 100644 --- a/src/responder/ssh/ssh_cmd.c +++ b/src/responder/ssh/ssh_cmd.c @@ -140,12 +140,10 @@ static void ssh_ext_debug(void *private, const char *file, long line, level = data->level; } - if (DEBUG_IS_SET(level)) { - va_start(ap, format); - sss_vdebug_fn(file, line, function, level, APPEND_LINE_FEED, - format, ap); - va_end(ap); - } + va_start(ap, format); + sss_vdebug_fn(file, line, function, level, APPEND_LINE_FEED, + format, ap); + va_end(ap); } static errno_t ssh_cmd_refresh_certmap_ctx(struct ssh_ctx *ssh_ctx, diff --git a/src/sbus/connection/sbus_watch.c b/src/sbus/connection/sbus_watch.c index 3abb66fa47..d1b55e9633 100644 --- a/src/sbus/connection/sbus_watch.c +++ b/src/sbus/connection/sbus_watch.c @@ -315,6 +315,7 @@ sbus_watch_toggle(DBusWatch *dbus_watch, void *data) struct sbus_watch_fd *watch_fd; dbus_bool_t is_enabled; unsigned int flags; + int fd; is_enabled = dbus_watch_get_enabled(dbus_watch); flags = dbus_watch_get_flags(dbus_watch); @@ -344,15 +345,13 @@ sbus_watch_toggle(DBusWatch *dbus_watch, void *data) } } - if (DEBUG_IS_SET(SSSDBG_TRACE_ALL)) { - int fd = sbus_watch_get_fd(dbus_watch); + fd = sbus_watch_get_fd(dbus_watch); - DEBUG(SSSDBG_TRACE_ALL, "Toggle to %s %s/%s watch on %d\n", - is_enabled ? "enabled" : "disabled", - (flags & DBUS_WATCH_READABLE) ? "R" : "-", - (flags & DBUS_WATCH_WRITABLE) ? "W" : "-", - fd); - } + DEBUG(SSSDBG_TRACE_ALL, "Toggle to %s %s/%s watch on %d\n", + is_enabled ? "enabled" : "disabled", + (flags & DBUS_WATCH_READABLE) ? "R" : "-", + (flags & DBUS_WATCH_WRITABLE) ? "W" : "-", + fd); } /** diff --git a/src/util/debug.h b/src/util/debug.h index 54a7e39346..29329dbd97 100644 --- a/src/util/debug.h +++ b/src/util/debug.h @@ -26,6 +26,8 @@ #include <stdio.h> #include <stdbool.h> +#include "util/util_errors.h" + #define SSSDBG_TIMESTAMP_UNRESOLVED -1 #define SSSDBG_TIMESTAMP_DEFAULT 1 @@ -128,15 +130,6 @@ int rotate_debug_files(void); } \ } while (0) -/** \def DEBUG_IS_SET(level) - \brief checks whether level is set in debug_level - - \param level the debug level, please use one of the SSSDBG*_ macros -*/ -#define DEBUG_IS_SET(level) (debug_level & (level) || \ - (debug_level == SSSDBG_UNRESOLVED && \ - (level & (SSSDBG_FATAL_FAILURE | \ - SSSDBG_CRIT_FAILURE)))) /* SSSD_*_OPTS are used as 'poptOption' entries */ #define SSSD_LOGGER_OPTS \ @@ -181,6 +174,18 @@ void sss_debug_fn(const char *file, #define APPEND_LINE_FEED 0x1 /* can be used as a sss_vdebug_fn() flag */ +/* Checks whether level is set in generic debug_level. + Rarely needed to be used explicitly as everything + should go to backtrace buffer anyway (regardless debug_level) + Deciding if "--verbose" should be passed to `adcli` child process + is one of usage examples. + */ +#define DEBUG_IS_SET(level) (debug_level & (level) || \ + (debug_level == SSSDBG_UNRESOLVED && \ + (level & (SSSDBG_FATAL_FAILURE | \ + SSSDBG_CRIT_FAILURE)))) + + /* not to be used explictly, use 'DEBUG_INIT' instead */ void _sss_debug_init(int dbg_lvl, const char *logger); void _sss_talloc_log_fn(const char *msg); diff --git a/src/util/sss_pam_data.h b/src/util/sss_pam_data.h index c989810541..674588daa2 100644 --- a/src/util/sss_pam_data.h +++ b/src/util/sss_pam_data.h @@ -34,7 +34,7 @@ #include "util/authtok.h" #define DEBUG_PAM_DATA(level, pd) do { \ - if (DEBUG_IS_SET(level)) pam_print_data(level, pd); \ + pam_print_data(level, pd); \ } while(0) struct response_data { diff --git a/src/util/sss_semanage.c b/src/util/sss_semanage.c index aea03852ac..10a567c9a9 100644 --- a/src/util/sss_semanage.c +++ b/src/util/sss_semanage.c @@ -55,10 +55,8 @@ static void sss_semanage_error_callback(void *varg, } va_start(ap, fmt); - if (DEBUG_IS_SET(level)) { - sss_vdebug_fn(__FILE__, __LINE__, "libsemanage", level, - APPEND_LINE_FEED, fmt, ap); - } + sss_vdebug_fn(__FILE__, __LINE__, "libsemanage", level, + APPEND_LINE_FEED, fmt, ap); va_end(ap); } diff --git a/src/util/tev_curl.c b/src/util/tev_curl.c index ebbcefc016..8c6fa291e0 100644 --- a/src/util/tev_curl.c +++ b/src/util/tev_curl.c @@ -196,15 +196,13 @@ static void handle_curlmsg_done(CURLMsg *message) return; } - if (DEBUG_IS_SET(SSSDBG_TRACE_FUNC)) { - crv = curl_easy_getinfo(easy_handle, CURLINFO_EFFECTIVE_URL, &done_url); - if (crv != CURLE_OK) { - DEBUG(SSSDBG_MINOR_FAILURE, "Cannot get CURLINFO_EFFECTIVE_URL " - "[%d]: %s\n", crv, curl_easy_strerror(crv)); - /* not fatal since we need this only for debugging */ - } else { - DEBUG(SSSDBG_TRACE_FUNC, "Handled %s\n", done_url); - } + crv = curl_easy_getinfo(easy_handle, CURLINFO_EFFECTIVE_URL, &done_url); + if (crv != CURLE_OK) { + DEBUG(SSSDBG_MINOR_FAILURE, "Cannot get CURLINFO_EFFECTIVE_URL " + "[%d]: %s\n", crv, curl_easy_strerror(crv)); + /* not fatal since we need this only for debugging */ + } else { + DEBUG(SSSDBG_TRACE_FUNC, "Handled %s\n", done_url); } crv = curl_easy_getinfo(easy_handle, CURLINFO_PRIVATE, (void *) &req); From b2a6b165b5e6aeafde2217991b2810ede139e14b Mon Sep 17 00:00:00 2001 From: Alexey Tikhonov <[email protected]> Date: Mon, 22 Mar 2021 14:58:22 +0100 Subject: [PATCH 2/9] DEBUG: poor man's backtrace :feature: In case SSSD is run with debug_level < 9, log everything to a ring buffer in memory and flush the buffer to a log file on any error (up to and including `min(0x0040, debug_level)`) (i.e. if `debug_level` is explicitly set to 0 or 1 then only those error levels will trigger backtrace, otherwise up to 2). Feature is only supported for `logger == files`. --- Makefile.am | 3 + src/tests/cmocka/dummy_child.c | 6 +- src/util/debug.c | 78 +++++---- src/util/debug.h | 11 +- src/util/debug_backtrace.c | 289 +++++++++++++++++++++++++++++++++ 5 files changed, 338 insertions(+), 49 deletions(-) create mode 100644 src/util/debug_backtrace.c diff --git a/Makefile.am b/Makefile.am index f4f71bdfdb..7d4bc24c3c 100644 --- a/Makefile.am +++ b/Makefile.am @@ -945,6 +945,7 @@ endif pkglib_LTLIBRARIES += libsss_debug.la libsss_debug_la_SOURCES = \ src/util/debug.c \ + src/util/debug_backtrace.c \ src/util/sss_log.c \ src/util/sss_cli_cmd.c \ $(NULL) @@ -1069,6 +1070,7 @@ pkglib_LTLIBRARIES += libsss_sbus.la libsss_sbus_la_SOURCES = \ src/util/check_and_open.c \ src/util/debug.c \ + src/util/debug_backtrace.c \ src/util/sss_ptr_hash.c \ src/util/sss_ptr_list.c \ src/util/sss_utf8.c \ @@ -1132,6 +1134,7 @@ libsss_sbus_la_LDFLAGS = \ pkglib_LTLIBRARIES += libsss_sbus_sync.la libsss_sbus_sync_la_SOURCES = \ src/util/debug.c \ + src/util/debug_backtrace.c \ src/util/sss_utf8.c \ src/util/util.c \ src/util/util_errors.c \ diff --git a/src/tests/cmocka/dummy_child.c b/src/tests/cmocka/dummy_child.c index 33b8c77fcb..8d0a2eb16b 100644 --- a/src/tests/cmocka/dummy_child.c +++ b/src/tests/cmocka/dummy_child.c @@ -42,6 +42,7 @@ int main(int argc, const char *argv[]) const char *action = NULL; const char *guitar; const char *drums; + int timestamp_opt; struct poptOption long_options[] = { POPT_AUTOHELP @@ -69,6 +70,7 @@ int main(int argc, const char *argv[]) poptFreeContext(pc); debug_log_file = "test_dummy_child"; + timestamp_opt = debug_timestamps; /* save value for verification */ DEBUG_INIT(debug_level, opt_logger); action = getenv("TEST_CHILD_ACTION"); @@ -80,7 +82,7 @@ int main(int argc, const char *argv[]) _exit(1); } } else if (strcasecmp(action, "check_only_extra_args") == 0) { - if (debug_timestamps == 1) { + if (timestamp_opt == 1) { DEBUG(SSSDBG_CRIT_FAILURE, "debug_timestamp was passed when only extra args " "should have been\n"); @@ -93,7 +95,7 @@ int main(int argc, const char *argv[]) _exit(1); } } else if (strcasecmp(action, "check_only_extra_args_neg") == 0) { - if (debug_timestamps != 1) { + if (timestamp_opt != 1) { DEBUG(SSSDBG_CRIT_FAILURE, "debug_timestamp was not passed as expected\n"); _exit(1); diff --git a/src/util/debug.c b/src/util/debug.c index 2e01311bf1..f87e85812a 100644 --- a/src/util/debug.c +++ b/src/util/debug.c @@ -36,6 +36,12 @@ #include "util/util.h" +/* from debug_backtrace.h */ +void sss_debug_backtrace_init(void); +void sss_debug_backtrace_vprintf(int level, const char *format, va_list ap); +void sss_debug_backtrace_printf(int level, const char *format, ...); +void sss_debug_backtrace_endmsg(int level); + const char *debug_prg_name = "sssd"; int debug_level = SSSDBG_UNRESOLVED; @@ -43,7 +49,7 @@ int debug_timestamps = SSSDBG_TIMESTAMP_UNRESOLVED; int debug_microseconds = SSSDBG_MICROSECONDS_UNRESOLVED; enum sss_logger_t sss_logger = STDERR_LOGGER; const char *debug_log_file = "sssd"; -static FILE *debug_file; +FILE *_sss_debug_file; const char *sss_logger_str[] = { [STDERR_LOGGER] = "stderr", @@ -97,17 +103,27 @@ void _sss_debug_init(int dbg_lvl, const char *logger) debug_level = SSSDBG_UNRESOLVED; } + if (debug_timestamps == SSSDBG_TIMESTAMP_UNRESOLVED) { + debug_timestamps = SSSDBG_TIMESTAMP_DEFAULT; + } + + if (debug_microseconds == SSSDBG_MICROSECONDS_UNRESOLVED) { + debug_microseconds = SSSDBG_MICROSECONDS_DEFAULT; + } + sss_set_logger(logger); /* if 'FILES_LOGGER' is requested then open log file, if it wasn't * initialized before via set_debug_file_from_fd(). */ - if ((sss_logger == FILES_LOGGER) && (debug_file == NULL)) { + if ((sss_logger == FILES_LOGGER) && (_sss_debug_file == NULL)) { if (_sss_open_debug_file() != 0) { ERROR("Error opening log file, falling back to stderr\n"); sss_logger = STDERR_LOGGER; } } + + sss_debug_backtrace_init(); } errno_t set_debug_file_from_fd(const int fd) @@ -129,18 +145,18 @@ errno_t set_debug_file_from_fd(const int fd) return ret; } - debug_file = dummy; + _sss_debug_file = dummy; return EOK; } int get_fd_from_debug_file(void) { - if (debug_file == NULL) { + if (_sss_debug_file == NULL) { return STDERR_FILENO; } - return fileno(debug_file); + return fileno(_sss_debug_file); } int debug_convert_old_level(int old_level) @@ -186,29 +202,6 @@ int debug_convert_old_level(int old_level) return new_level; } -static void debug_fflush(void) -{ - fflush(debug_file ? debug_file : stderr); -} - -static void debug_vprintf(const char *format, va_list ap) -{ - vfprintf(debug_file ? debug_file : stderr, format, ap); -} - -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); - - debug_vprintf(format, ap); - - va_end(ap); -} #ifdef WITH_JOURNALD static errno_t journal_send(const char *file, @@ -292,6 +285,7 @@ void sss_vdebug_fn(const char *file, va_list ap_fallback; if (sss_logger == JOURNALD_LOGGER) { + if (!DEBUG_IS_SET(level)) return; /* no debug backtrace with journald atm */ /* If we are not outputting logs to files, we should be sending them * to journald. * NOTE: on modern systems, this is where stdout/stderr will end up @@ -303,8 +297,8 @@ void sss_vdebug_fn(const char *file, ret = journal_send(file, line, function, level, format, ap); if (ret != EOK) { /* Emergency fallback, send to STDERR */ - debug_vprintf(format, ap_fallback); - debug_fflush(); + vfprintf(stderr, format, ap_fallback); + fflush(stderr); } va_end(ap_fallback); return; @@ -327,19 +321,21 @@ void sss_vdebug_fn(const char *file, tm.tm_hour, tm.tm_min, tm.tm_sec); } if (debug_microseconds) { - debug_printf("%s:%.6ld): ", last_time_str, tv.tv_usec); + sss_debug_backtrace_printf(level, "%s:%.6ld): ", + last_time_str, tv.tv_usec); } else { - debug_printf("%s): ", last_time_str); + sss_debug_backtrace_printf(level, "%s): ", last_time_str); } } - debug_printf("[%s] [%s] (%#.4x): ", debug_prg_name, function, level); + sss_debug_backtrace_printf(level, "[%s] [%s] (%#.4x): ", + debug_prg_name, function, level); - debug_vprintf(format, ap); + sss_debug_backtrace_vprintf(level, format, ap); if (flags & APPEND_LINE_FEED) { - debug_printf("\n"); + sss_debug_backtrace_printf(level, "\n"); } - debug_fflush(); + sss_debug_backtrace_endmsg(level); } void sss_debug_fn(const char *file, @@ -416,7 +412,7 @@ int open_debug_file_ex(const char *filename, FILE **filep, bool want_cloexec) return ENOMEM; } - if (debug_file && !filep) fclose(debug_file); + if (_sss_debug_file && !filep) fclose(_sss_debug_file); old_umask = umask(SSS_DFL_UMASK); errno = 0; @@ -442,7 +438,7 @@ int open_debug_file_ex(const char *filename, FILE **filep, bool want_cloexec) } if (filep == NULL) { - debug_file = f; + _sss_debug_file = f; } else { *filep = f; } @@ -457,10 +453,10 @@ int rotate_debug_files(void) if (sss_logger != FILES_LOGGER) return EOK; - if (debug_file != NULL) { + if (_sss_debug_file != NULL) { do { error = 0; - ret = fclose(debug_file); + ret = fclose(_sss_debug_file); if (ret != 0) { error = errno; } @@ -486,7 +482,7 @@ int rotate_debug_files(void) } } - debug_file = NULL; + _sss_debug_file = NULL; return _sss_open_debug_file(); } diff --git a/src/util/debug.h b/src/util/debug.h index 29329dbd97..b7e41dd8e4 100644 --- a/src/util/debug.h +++ b/src/util/debug.h @@ -63,6 +63,8 @@ extern const char *debug_log_file; /* only file name, excluding path */ DEBUG_INIT(dbg_lvl, sss_logger_str[STDERR_LOGGER]); \ } while (0) +void sss_debug_backtrace_enable(bool enable); + /* debug_convert_old_level() converts "old" style decimal notation * to bitmask composed of SSSDBG_* * Used explicitly, for example, while processing user input @@ -122,12 +124,9 @@ int rotate_debug_files(void); \param ... the debug message format arguments */ #define DEBUG(level, format, ...) do { \ - int __debug_macro_level = level; \ - if (DEBUG_IS_SET(__debug_macro_level)) { \ - sss_debug_fn(__FILE__, __LINE__, __FUNCTION__, \ - __debug_macro_level, \ - format, ##__VA_ARGS__); \ - } \ + sss_debug_fn(__FILE__, __LINE__, __FUNCTION__, \ + level, \ + format, ##__VA_ARGS__); \ } while (0) diff --git a/src/util/debug_backtrace.c b/src/util/debug_backtrace.c new file mode 100644 index 0000000000..4eccebb3ab --- /dev/null +++ b/src/util/debug_backtrace.c @@ -0,0 +1,289 @@ +/* + Copyright (C) 2021 Red Hat + + This program is free software; you can redistribute it and/or modify + it under the terms of the GNU General Public License as published by + the Free Software Foundation; either version 3 of the License, or + (at your option) any later version. + + This program is distributed in the hope that it will be useful, + but WITHOUT ANY WARRANTY; without even the implied warranty of + MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + GNU General Public License for more details. + + You should have received a copy of the GNU General Public License + along with this program. If not, see <http://www.gnu.org/licenses/>. +*/ + +#include <stdbool.h> +#include <stdlib.h> +#include <libintl.h> +#include <stdarg.h> +#include <stdio.h> +#include <string.h> + +#include "util/debug.h" + +extern FILE *_sss_debug_file; + + +static const unsigned SSS_DEBUG_BACKTRACE_DEFAULT_SIZE = 100*1024; /* bytes */ +static const unsigned SSS_DEBUG_BACKTRACE_LEVEL = SSSDBG_BE_FO; + + +/* --> + * ring buffer = [*******t...\n............e000] + * where: + * "t" - 'tail', "e" - 'end' + * "......" - "old" part of buffer + * "******" - "new" part of buffer + * "000" - unoccupied space + */ +static struct { + bool enabled; + bool initialized; + int size; + char *buffer; /* buffer start */ + char *end; /* end data border */ + char *tail; /* tail of "current" message */ +} _bt; + + +static inline bool _all_levels_enabled(void); +static inline bool _backtrace_is_enabled(int level); +static inline bool _is_trigger_level(int level); +static void _backtrace_vprintf(const char *format, va_list ap); +static void _backtrace_printf(const char *format, ...); +static void _backtrace_dump(void); +static inline void _debug_vprintf(const char *format, va_list ap); +static inline void _debug_fwrite(const char *ptr, const char *end); +static inline void _debug_fflush(void); + + +void sss_debug_backtrace_init(void) +{ + _bt.size = SSS_DEBUG_BACKTRACE_DEFAULT_SIZE; + _bt.buffer = (char *)malloc(_bt.size); + if (!_bt.buffer) { + ERROR("Failed to allocate debug backtrace buffer, feature is off\n"); + return; + } + + _bt.end = _bt.buffer; + _bt.tail = _bt.buffer; + + _bt.enabled = true; + _bt.initialized = true; + + _backtrace_printf(" * "); +} + + +void sss_debug_backtrace_enable(bool enable) +{ + _bt.enabled = enable; +} + + +void sss_debug_backtrace_vprintf(int level, const char *format, va_list ap) +{ + va_list ap_copy; + + /* Potential optimization: only print to file here if backtrace is disabled, + * otherwise always print message to backtrace only and then copy message + * from backtrace to file in sss_debug_backtrace_endmsg(). + * This saves va_copy and another round of format parsing inside printf but + * results in a little bit less readable output. + */ + if (DEBUG_IS_SET(level)) { + va_copy(ap_copy, ap); + _debug_vprintf(format, ap_copy); + va_end(ap_copy); + } + + if (_backtrace_is_enabled(level)) { + _backtrace_vprintf(format, ap); + } +} + + +void sss_debug_backtrace_printf(int level, const char *format, ...) +{ + va_list ap; + va_start(ap, format); + sss_debug_backtrace_vprintf(level, format, ap); + va_end(ap); +} + + +void sss_debug_backtrace_endmsg(int level) +{ + if (DEBUG_IS_SET(level)) { + _debug_fflush(); + } + + if (_backtrace_is_enabled(level)) { + if (_is_trigger_level(level)) { + _backtrace_dump(); + } + _backtrace_printf(" * "); + } +} + + + + +/* ********** Helpers ********** */ + + +static inline void _debug_vprintf(const char *format, va_list ap) +{ + vfprintf(_sss_debug_file ? _sss_debug_file : stderr, format, ap); +} + + +static inline void _debug_fwrite(const char *begin, const char *end) +{ + if (end <= begin) { + return; + } + size_t size = (end - begin); + fwrite_unlocked(begin, size, 1, _sss_debug_file ? _sss_debug_file : stderr); +} + + +static inline void _debug_fflush(void) +{ + fflush(_sss_debug_file ? _sss_debug_file : stderr); +} + + + /* does 'level' trigger backtrace dump? */ +static inline bool _is_trigger_level(int level) +{ + return ((level <= SSSDBG_OP_FAILURE) && + (level <= debug_level)); +} + + +/* checks if global 'debug_level' has all levels up to 9 enabled */ +static inline bool _all_levels_enabled(void) +{ + static const unsigned all_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|SSSDBG_BE_FO; + + unsigned level = debug_level & ~SSSDBG_TRACE_LDB; + + return ((level ^ all_levels) == 0); +} + + +/* should message of this 'level' go to backtrace? */ +static inline bool _backtrace_is_enabled(int level) +{ + /* Store message in backtrace buffer if: */ + return (_bt.initialized && /* backtrace is initialized */ + _bt.enabled && /* backtrace is enabled */ + sss_logger != STDERR_LOGGER && + !_all_levels_enabled() && /* generic log doesn't cover everything */ + level <= SSS_DEBUG_BACKTRACE_LEVEL); /* skip SSSDBG_TRACE_LDB */ +} + + + /* prints to buffer */ +static void _backtrace_vprintf(const char *format, va_list ap) +{ + int buff_tail_size = _bt.size - (_bt.tail - _bt.buffer); + int written; + + /* make sure there is at least 1kb available to avoid truncation; + * putting a sane limit on the size of single message (1kb in a worst case) + * makes logic simpler and avoids performance hit + */ + if (buff_tail_size < 1024) { + /* let's wrap */ + _bt.end = _bt.tail; + _bt.tail = _bt.buffer; + buff_tail_size = _bt.size; + } + + written = vsnprintf(_bt.tail, buff_tail_size, format, ap); + if (written >= buff_tail_size) { + /* message is > 1kb, just discard */ + return; + } + + _bt.tail += written; + if (_bt.tail > _bt.end) { + _bt.end = _bt.tail; + } +} + + +static void _backtrace_printf(const char *format, ...) +{ + va_list ap; + va_start(ap, format); + _backtrace_vprintf(format, ap); + va_end(ap); +} + + +static bool _bt_empty(const char *begin, const char *end) +{ + int counter = 0; + + while (begin < end) { + if (*begin == '\n') { + counter++; + if (counter == 2) { + /* there is least one line in addition to trigger msg */ + return false; + } + } + begin++; + } + + return true; +} + + +static void _backtrace_dump(void) +{ + const char *start = NULL; + static const char *start_marker = + "********************** PREVIOUS MESSAGE WAS TRIGGERED BY THE FOLLOWING BACKTRACE:\n"; + static const char *end_marker = + "********************** BACKTRACE DUMP ENDS HERE *********************************\n\n"; + + if (_bt.end > _bt.tail) { + /* there is something in the "old" part, but don't start mid message */ + start = _bt.tail + 1; + while ((start < _bt.end) && (*start != '\n')) start++; + if (start >= _bt.end) start = NULL; + } + + if (!start) { + /* do we have anything to dump at all? */ + if (_bt_empty(_bt.buffer, _bt.tail)) { + return; + } + } + + fprintf(_sss_debug_file ? _sss_debug_file : stderr, "%s", start_marker); + + if (start) { + _debug_fwrite(start + 1, _bt.end); /* dump "old" part of buffer */ + } + _debug_fwrite(_bt.buffer, _bt.tail); /* dump "new" part of buffer */ + + fprintf(_sss_debug_file ? _sss_debug_file : stderr, "%s", end_marker); + _debug_fflush(); + + _bt.end = _bt.buffer; + _bt.tail = _bt.buffer; +} + From 1e3ecd510d00f7b3d4ad22a3c92cced343e66437 Mon Sep 17 00:00:00 2001 From: Alexey Tikhonov <[email protected]> Date: Wed, 31 Mar 2021 11:48:58 +0200 Subject: [PATCH 3/9] PAM: fixes a couple of covscan issues Fixes: ``` Error: COMPILER_WARNING (CWE-758): sssd-2.4.3/src/util/debug.h:127:5: warning[-Wformat-overflow=]: '%.*s' directive argument is null # 127 | sss_debug_fn(__FILE__, __LINE__, __FUNCTION__, \ # | ^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ # 128 | level, \ # | ~~~~~~~~ # 129 | format, ##__VA_ARGS__); \ # | ~~~~~~~~~~~~~~~~~~~~~~ sssd-2.4.3/src/responder/pam/pamsrv_cmd.c: scope_hint: In function 'filter_responses' sssd-2.4.3/src/responder/pam/pamsrv_cmd.c:569:51: note: format string is defined here # 569 | "Found PAM ENV filter for variable [%.*s] and service [%s].\n", # | ^~~~ ``` and ``` Error: COMPILER_WARNING (CWE-758): sssd-2.4.3/src/util/util.h:47: included_from: Included from here. sssd-2.4.3/src/responder/pam/pamsrv_cmd.c:24: included_from: Included from here. sssd-2.4.3/src/responder/pam/pamsrv_cmd.c: scope_hint: In function 'pam_check_user_search_next' sssd-2.4.3/src/util/debug.h:127:5: warning[-Wformat-overflow=]: '%s' directive argument is null # 127 | sss_debug_fn(__FILE__, __LINE__, __FUNCTION__, \ # | ^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ # 128 | level, \ # | ~~~~~~~~ # 129 | format, ##__VA_ARGS__); \ # | ~~~~~~~~~~~~~~~~~~~~~~ sssd-2.4.3/src/responder/pam/pamsrv_cmd.c:1947:53: note: format string is defined here # 1947 | DEBUG(SSSDBG_TRACE_ALL, "PAM initgroups scheme [%s].\n", # | ^~ ``` --- src/responder/pam/pamsrv_cmd.c | 9 ++++++--- 1 file changed, 6 insertions(+), 3 deletions(-) diff --git a/src/responder/pam/pamsrv_cmd.c b/src/responder/pam/pamsrv_cmd.c index d052ca7528..c503801f69 100644 --- a/src/responder/pam/pamsrv_cmd.c +++ b/src/responder/pam/pamsrv_cmd.c @@ -68,7 +68,8 @@ enum pam_initgroups_scheme pam_initgroups_string_to_enum(const char *str) return PAM_INITGR_INVALID; } -const char *pam_initgroup_enum_to_string(enum pam_initgroups_scheme scheme) { +const char *pam_initgroup_enum_to_string(enum pam_initgroups_scheme scheme) +{ size_t c; for (c = 0 ; pam_initgroup_enum_str[c].option != NULL; c++) { @@ -77,7 +78,7 @@ const char *pam_initgroup_enum_to_string(enum pam_initgroups_scheme scheme) { } } - return NULL; + return "(NULL)"; } @@ -567,7 +568,9 @@ static errno_t filter_responses_env(struct response_data *resp, DEBUG(SSSDBG_TRACE_ALL, "Found PAM ENV filter for variable [%.*s] and service [%s].\n", - (int) var_name_len, var_name, service); + (int) var_name_len, + (var_name ? var_name : "(NULL)"), + (service ? service : "(NULL)")); if (service != NULL && pd->service != NULL && strcmp(service, pd->service) != 0) { From 6c5524c67ff444fbc5dc4506b81253e6b984b838 Mon Sep 17 00:00:00 2001 From: Alexey Tikhonov <[email protected]> Date: Sat, 10 Apr 2021 19:57:55 +0200 Subject: [PATCH 4/9] CACHE_REQ: fixed REVERSE_INULL warning Fixes following warning: ``` sssd-2.4.3/src/responder/common/cache_req/cache_req.c:807: check_after_deref: Null-checking "domain" suggests that it may be null, but it has already been dereferenced on all paths leading to the check. sssd-2.4.3/src/responder/common/cache_req/cache_req.c:784: deref_ptr: Directly dereferencing pointer "domain". sssd-2.4.3/src/responder/common/cache_req/cache_req.c:790: deref_ptr_in_call: Dereferencing pointer "domain". sssd-2.4.3/src/responder/common/cache_req/cache_req.c:805: alias: Assigning: "state->selected_domain" = "domain". # 805| state->selected_domain = domain; # 806| # 807|-> if (domain == NULL) { # 808| break; # 809| } ``` --- src/responder/common/cache_req/cache_req.c | 9 +++++---- 1 file changed, 5 insertions(+), 4 deletions(-) diff --git a/src/responder/common/cache_req/cache_req.c b/src/responder/common/cache_req/cache_req.c index c6902f8424..abff0d4957 100644 --- a/src/responder/common/cache_req/cache_req.c +++ b/src/responder/common/cache_req/cache_req.c @@ -777,6 +777,11 @@ static errno_t cache_req_search_domains_next(struct tevent_req *req) while (state->cr_domain != NULL) { domain = state->cr_domain->domain; + + if (domain == NULL) { + break; + } + /* As the cr_domain list is a flatten version of the domains * list, we have to ensure to only go through the subdomains in * case it's specified in the plugin to do so. @@ -804,10 +809,6 @@ static errno_t cache_req_search_domains_next(struct tevent_req *req) state->selected_domain = domain; - if (domain == NULL) { - break; - } - ret = cache_req_set_domain(cr, domain); if (ret != EOK) { return ret; From c324254bc20cf9e0ca6055d8642dc7a2f04af4cd Mon Sep 17 00:00:00 2001 From: Alexey Tikhonov <[email protected]> Date: Sat, 10 Apr 2021 22:01:59 +0200 Subject: [PATCH 5/9] DEBUG: makes debug backtrace switchable :config: Introduced new option 'debug_backtrace_enabled' to control debug backtrace. --- src/confdb/confdb.h | 1 + src/config/SSSDConfig/sssdoptions.py | 1 + src/config/SSSDConfigTest.py | 1 + src/config/cfg_rules.ini | 11 +++++++++++ src/config/etc/sssd.api.conf | 1 + src/man/sssd.conf.5.xml | 24 ++++++++++++++++++++++++ src/util/server.c | 12 ++++++++++++ 7 files changed, 51 insertions(+) diff --git a/src/confdb/confdb.h b/src/confdb/confdb.h index c6c2514f83..2290217739 100644 --- a/src/confdb/confdb.h +++ b/src/confdb/confdb.h @@ -61,6 +61,7 @@ #define CONFDB_SERVICE_DEBUG_LEVEL_ALIAS "debug" #define CONFDB_SERVICE_DEBUG_TIMESTAMPS "debug_timestamps" #define CONFDB_SERVICE_DEBUG_MICROSECONDS "debug_microseconds" +#define CONFDB_SERVICE_DEBUG_BACKTRACE_ENABLED "debug_backtrace_enabled" #define CONFDB_SERVICE_RECON_RETRIES "reconnection_retries" #define CONFDB_SERVICE_FD_LIMIT "fd_limit" #define CONFDB_SERVICE_ALLOWED_UIDS "allowed_uids" diff --git a/src/config/SSSDConfig/sssdoptions.py b/src/config/SSSDConfig/sssdoptions.py index 550e63f6ba..696857c1d9 100644 --- a/src/config/SSSDConfig/sssdoptions.py +++ b/src/config/SSSDConfig/sssdoptions.py @@ -21,6 +21,7 @@ def __init__(self): 'debug_level': _('Set the verbosity of the debug logging'), 'debug_timestamps': _('Include timestamps in debug logs'), 'debug_microseconds': _('Include microseconds in timestamps in debug logs'), + 'debug_backtrace_enabled': _('Enable/disable debug backtrace'), 'timeout': _('Watchdog timeout before restarting service'), 'command': _('Command to start service'), 'reconnection_retries': _('Number of times to attempt connection to Data Providers'), diff --git a/src/config/SSSDConfigTest.py b/src/config/SSSDConfigTest.py index 61d24b6014..b453c01d46 100755 --- a/src/config/SSSDConfigTest.py +++ b/src/config/SSSDConfigTest.py @@ -381,6 +381,7 @@ def testListOptions(self): 'debug_level', 'debug_timestamps', 'debug_microseconds', + 'debug_backtrace_enabled', 'command', 'reconnection_retries', 'fd_limit', diff --git a/src/config/cfg_rules.ini b/src/config/cfg_rules.ini index f3a1783d81..149b4d78ef 100644 --- a/src/config/cfg_rules.ini +++ b/src/config/cfg_rules.ini @@ -32,6 +32,7 @@ option = debug option = debug_level option = debug_timestamps option = debug_microseconds +option = debug_backtrace_enabled option = command option = reconnection_retries option = fd_limit @@ -66,6 +67,7 @@ option = debug option = debug_level option = debug_timestamps option = debug_microseconds +option = debug_backtrace_enabled option = command option = reconnection_retries option = fd_limit @@ -107,6 +109,7 @@ option = debug option = debug_level option = debug_timestamps option = debug_microseconds +option = debug_backtrace_enabled option = command option = reconnection_retries option = fd_limit @@ -150,6 +153,7 @@ option = debug option = debug_level option = debug_timestamps option = debug_microseconds +option = debug_backtrace_enabled option = command option = reconnection_retries option = fd_limit @@ -172,6 +176,7 @@ option = debug option = debug_level option = debug_timestamps option = debug_microseconds +option = debug_backtrace_enabled option = command option = reconnection_retries option = fd_limit @@ -192,6 +197,7 @@ option = debug option = debug_level option = debug_timestamps option = debug_microseconds +option = debug_backtrace_enabled option = command option = reconnection_retries option = fd_limit @@ -216,6 +222,7 @@ option = debug option = debug_level option = debug_timestamps option = debug_microseconds +option = debug_backtrace_enabled option = command option = reconnection_retries option = fd_limit @@ -237,6 +244,7 @@ option = debug option = debug_level option = debug_timestamps option = debug_microseconds +option = debug_backtrace_enabled option = command option = reconnection_retries option = fd_limit @@ -259,6 +267,7 @@ option = debug option = debug_level option = debug_timestamps option = debug_microseconds +option = debug_backtrace_enabled option = command option = reconnection_retries option = fd_limit @@ -309,6 +318,7 @@ option = debug option = debug_level option = debug_timestamps option = debug_microseconds +option = debug_backtrace_enabled option = command option = reconnection_retries option = fd_limit @@ -370,6 +380,7 @@ option = debug option = debug_level option = debug_timestamps option = debug_microseconds +option = debug_backtrace_enabled option = command option = reconnection_retries option = fd_limit diff --git a/src/config/etc/sssd.api.conf b/src/config/etc/sssd.api.conf index 3627483885..b882aa5e53 100644 --- a/src/config/etc/sssd.api.conf +++ b/src/config/etc/sssd.api.conf @@ -8,6 +8,7 @@ debug = int, None, false debug_level = int, None, false debug_timestamps = bool, None, false debug_microseconds = bool, None, false +debug_backtrace_enabled = bool, None, false command = str, None, false reconnection_retries = int, None, false fd_limit = int, None, false diff --git a/src/man/sssd.conf.5.xml b/src/man/sssd.conf.5.xml index b3645fbc09..31a698e3d2 100644 --- a/src/man/sssd.conf.5.xml +++ b/src/man/sssd.conf.5.xml @@ -147,6 +147,30 @@ </para> </listitem> </varlistentry> + <varlistentry> + <term>debug_backtrace_enabled (bool)</term> + <listitem> + <para> + Enable debug backtrace. + </para> + <para> + In case SSSD is run with debug_level less than 9, + everything is logged to a ring buffer in memory and + flushed to a log file on any error up to + and including `min(0x0040, debug_level)` + (i.e. if debug_level is explicitly set to 0 or 1 then + only those error levels will trigger backtrace, + otherwise up to 2). + </para> + <para> + Feature is only supported for `logger == files` (i.e. + setting doesn't have effect for other logger types). + </para> + <para> + Default: true + </para> + </listitem> + </varlistentry> </variablelist> </para> </refsect2> diff --git a/src/util/server.c b/src/util/server.c index 9c4273f305..fa3db39590 100644 --- a/src/util/server.c +++ b/src/util/server.c @@ -455,6 +455,7 @@ int server_setup(const char *name, int flags, int ret = EOK; bool dt; bool dm; + bool backtrace_enabled; struct tevent_signal *tes; struct logrotate_ctx *lctx; char *locale; @@ -642,6 +643,17 @@ int server_setup(const char *name, int flags, else debug_microseconds = 0; } + ret = confdb_get_bool(ctx->confdb_ctx, conf_entry, + CONFDB_SERVICE_DEBUG_BACKTRACE_ENABLED, + true, + &backtrace_enabled); + if (ret != EOK) { + DEBUG(SSSDBG_FATAL_FAILURE, "Error reading %s from confdb (%d) [%s]\n", + CONFDB_SERVICE_DEBUG_BACKTRACE_ENABLED, ret, strerror(ret)); + return ret; + } + sss_debug_backtrace_enable(backtrace_enabled); + /* before opening the log file set up log rotation */ lctx = talloc_zero(ctx, struct logrotate_ctx); if (!lctx) return ENOMEM; From 9db49e171e3408850929c49a3b5dacc52f960ed7 Mon Sep 17 00:00:00 2001 From: Alexey Tikhonov <[email protected]> Date: Sun, 11 Apr 2021 11:55:11 +0200 Subject: [PATCH 6/9] DEBUG: log IMPORTANT_INFO if any bit >= OP_FAILURE is on This makes sense in general and ensures IMPORTANT_INFO doesn't trigger backtrace dump. --- src/util/debug.h | 8 +++++++- 1 file changed, 7 insertions(+), 1 deletion(-) diff --git a/src/util/debug.h b/src/util/debug.h index b7e41dd8e4..97564d43e2 100644 --- a/src/util/debug.h +++ b/src/util/debug.h @@ -107,7 +107,13 @@ int rotate_debug_files(void); #define SSSDBG_TRACE_ALL 0x4000 /* level 9 */ #define SSSDBG_BE_FO 0x8000 /* level 9 */ #define SSSDBG_TRACE_LDB 0x10000 /* level 10 */ -#define SSSDBG_IMPORTANT_INFO SSSDBG_OP_FAILURE + +/* IMPORTANT_INFO will be logged if any of bits >= OP_FAILURE are on: */ +#define SSSDBG_IMPORTANT_INFO (SSSDBG_OP_FAILURE|SSSDBG_MINOR_FAILURE|\ + SSSDBG_CONF_SETTINGS|SSSDBG_FUNC_DATA|\ + SSSDBG_TRACE_FUNC|SSSDBG_TRACE_LIBS|\ + SSSDBG_TRACE_INTERNAL|SSSDBG_TRACE_ALL|\ + SSSDBG_BE_FO|SSSDBG_TRACE_LDB) #define SSSDBG_INVALID -1 #define SSSDBG_UNRESOLVED 0 From b517260b1f17a1c053c1dd2628f486c3ebc17838 Mon Sep 17 00:00:00 2001 From: Alexey Tikhonov <[email protected]> Date: Sun, 11 Apr 2021 17:24:13 +0200 Subject: [PATCH 7/9] CERTMAP: removed "sss_certmap initialized" debug Most lib users expect only errors to be logged and provide logger function with SSSDBG_OP_FAILURE debug level. Thus "sss_certmap initialized" was triggering backtrace dump for no reason. --- src/lib/certmap/sss_certmap.c | 1 - 1 file changed, 1 deletion(-) diff --git a/src/lib/certmap/sss_certmap.c b/src/lib/certmap/sss_certmap.c index f19e577320..d1747f20de 100644 --- a/src/lib/certmap/sss_certmap.c +++ b/src/lib/certmap/sss_certmap.c @@ -932,7 +932,6 @@ int sss_certmap_init(TALLOC_CTX *mem_ctx, return ret; } - CM_DEBUG((*ctx), "sss_certmap initialized."); return EOK; } From b3b9197670a1e9391f0a27c7b466a390311c8356 Mon Sep 17 00:00:00 2001 From: Alexey Tikhonov <[email protected]> Date: Wed, 14 Apr 2021 14:00:49 +0200 Subject: [PATCH 8/9] SERVER: decrease log level in `orderly_shutdown()` to avoid backtrace in this case. --- src/util/server.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/util/server.c b/src/util/server.c index fa3db39590..b6f450a798 100644 --- a/src/util/server.c +++ b/src/util/server.c @@ -244,7 +244,7 @@ void orderly_shutdown(int status) if (sent_sigterm == 0 && getpgrp() == getpid()) { debug = is_socket_activated() ? SSSDBG_TRACE_INTERNAL - : SSSDBG_FATAL_FAILURE; + : SSSDBG_IMPORTANT_INFO; DEBUG(debug, "SIGTERM: killing children\n"); sent_sigterm = 1; kill(-getpgrp(), SIGTERM); From 45f568b674932e5ceacb4ff84bcb1e1a59f1ef6c Mon Sep 17 00:00:00 2001 From: Alexey Tikhonov <[email protected]> Date: Wed, 28 Apr 2021 14:55:18 +0200 Subject: [PATCH 9/9] SBUS: changed debug level in sbus_issue_request_done() to avoid backtrace dump in case of 'ERR_MISSING_DP_TARGET' --- src/sbus/router/sbus_router_handler.c | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/src/sbus/router/sbus_router_handler.c b/src/sbus/router/sbus_router_handler.c index a92cf524b3..9420400054 100644 --- a/src/sbus/router/sbus_router_handler.c +++ b/src/sbus/router/sbus_router_handler.c @@ -137,7 +137,9 @@ static void sbus_issue_request_done(struct tevent_req *subreq) DEBUG(SSSDBG_TRACE_FUNC, "%s.%s: Success\n", meta.interface, meta.member); } else { - DEBUG(SSSDBG_OP_FAILURE, "%s.%s: Error [%d]: %s\n", + int msg_level = SSSDBG_OP_FAILURE; + if (ret == ERR_MISSING_DP_TARGET) msg_level = SSSDBG_FUNC_DATA; + DEBUG(msg_level, "%s.%s: Error [%d]: %s\n", meta.interface, meta.member, ret, sss_strerror(ret)); }
_______________________________________________ sssd-devel mailing list -- [email protected] To unsubscribe send an email to [email protected] Fedora Code of Conduct: https://docs.fedoraproject.org/en-US/project/code-of-conduct/ List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedorahosted.org/archives/list/[email protected] Do not reply to spam on the list, report it: https://pagure.io/fedora-infrastructure
