URL: https://github.com/SSSD/sssd/pull/5585
Author: alexey-tikhonov
Title: #5585: Poor man's backtrace.
Action: opened
PR body:
"""
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`.
Feature is configurable via 'debug_backtrace_enabled' option.
"""
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 d6aa917c139081995453032acfefc38a2785429a Mon Sep 17 00:00:00 2001
From: Alexey Tikhonov <[email protected]>
Date: Fri, 19 Mar 2021 20:38:58 +0100
Subject: [PATCH 1/8] 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 fba928f4a3b15592cdffa93a3dff73eb1d7f5f98 Mon Sep 17 00:00:00 2001
From: Alexey Tikhonov <[email protected]>
Date: Mon, 22 Mar 2021 14:58:22 +0100
Subject: [PATCH 2/8] 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 d8cf3cc67ce09f5b036e7ff14097024f14c076e5 Mon Sep 17 00:00:00 2001
From: Alexey Tikhonov <[email protected]>
Date: Wed, 31 Mar 2021 11:48:58 +0200
Subject: [PATCH 3/8] 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 2489279d887e166075298620a470e064a2b5abd0 Mon Sep 17 00:00:00 2001
From: Alexey Tikhonov <[email protected]>
Date: Sat, 10 Apr 2021 19:57:55 +0200
Subject: [PATCH 4/8] 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 b5da62904146088abbf34566509851f4d57b9c1c Mon Sep 17 00:00:00 2001
From: Alexey Tikhonov <[email protected]>
Date: Sat, 10 Apr 2021 22:01:59 +0200
Subject: [PATCH 5/8] 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 0b31ebe00d..56fdfc4785 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 bdf4b3759b..0d0f5e49d3 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 c1ea02c6cb..14d3303d41 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 e8fb0195ad..f92f1b090c 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 b3aa927aaa..fc32b04154 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 a7edf5f99b8b9ff8d1af3e283bdb37342f7dc3ec Mon Sep 17 00:00:00 2001
From: Alexey Tikhonov <[email protected]>
Date: Sun, 11 Apr 2021 11:55:11 +0200
Subject: [PATCH 6/8] 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 fa69c31f04496a240cb9162ecb796e365445d464 Mon Sep 17 00:00:00 2001
From: Alexey Tikhonov <[email protected]>
Date: Sun, 11 Apr 2021 17:24:13 +0200
Subject: [PATCH 7/8] 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 55328ecbb7022344b407181328e606a079434727 Mon Sep 17 00:00:00 2001
From: Alexey Tikhonov <[email protected]>
Date: Wed, 14 Apr 2021 14:00:49 +0200
Subject: [PATCH 8/8] 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);
_______________________________________________
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
