URL: https://github.com/SSSD/sssd/pull/5666 Author: pbrezina Title: #5666: debug: add support for tevent chain id Action: synchronized
To pull the PR as Git branch: git remote add ghsssd https://github.com/SSSD/sssd git fetch ghsssd pull/5666/head:pr5666 git checkout pr5666
From 709f8ff64b3820d70d29aa5c7519134bc772d0ac Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Pavel=20B=C5=99ezina?= <[email protected]> Date: Tue, 11 May 2021 14:40:11 +0200 Subject: [PATCH 1/2] debug: add support for tevent chain id --- Makefile.am | 2 + src/external/libtevent.m4 | 29 +++++++ src/util/debug.c | 6 ++ src/util/sss_chain_id.c | 155 ++++++++++++++++++++++++++++++++++++++ src/util/sss_chain_id.h | 30 ++++++++ 5 files changed, 222 insertions(+) create mode 100644 src/util/sss_chain_id.c create mode 100644 src/util/sss_chain_id.h diff --git a/Makefile.am b/Makefile.am index 18ce3a2ddd..9a606b322b 100644 --- a/Makefile.am +++ b/Makefile.am @@ -697,6 +697,7 @@ dist_noinst_HEADERS = \ src/util/session_recording.h \ src/util/strtonum.h \ src/util/sss_cli_cmd.h \ + src/util/sss_chain_id.h \ src/util/sss_ptr_hash.h \ src/util/sss_ptr_list.h \ src/util/sss_endian.h \ @@ -1280,6 +1281,7 @@ libsss_util_la_SOURCES = \ src/util/files.c \ src/util/selinux.c \ src/util/sss_regexp.c \ + src/util/sss_chain_id.c \ $(NULL) libsss_util_la_CFLAGS = \ $(AM_CFLAGS) \ diff --git a/src/external/libtevent.m4 b/src/external/libtevent.m4 index d3df1d062d..25d43d38f6 100644 --- a/src/external/libtevent.m4 +++ b/src/external/libtevent.m4 @@ -13,3 +13,32 @@ AS_IF([test x"$found_tevent" != xyes], [-L$sss_extra_libdir -ltalloc])], [AC_MSG_ERROR([tevent header files are not installed])])] ) + +SAVE_CFLAGS=$CFLAGS +SAVE_LIBS=$LIBS +CFLAGS="$CFLAGS $TEVENT_CFLAGS" +LIBS="$LIBS $TEVENT_LIBS" +build_chain_id=yes +AC_CHECK_FUNCS([tevent_set_trace_fd_callback \ + tevent_set_trace_signal_callback \ + tevent_set_trace_timer_callback \ + tevent_set_trace_immediate_callback \ + tevent_fd_set_tag \ + tevent_fd_get_tag \ + tevent_signal_set_tag \ + tevent_signal_get_tag \ + tevent_timer_set_tag \ + tevent_timer_get_tag \ + tevent_immediate_set_tag \ + tevent_immediate_get_tag], + [], + [build_chain_id=no]) +CFLAGS=$SAVE_CFLAGS +LIBS=$SAVE_LIBS + +if test x$build_chain_id = xyes +then + AC_DEFINE(BUILD_CHAIN_ID, 1, [Build chain id]) +else + AC_MSG_NOTICE([Chain id support is disabled due to missing dependencies in tevent]) +fi diff --git a/src/util/debug.c b/src/util/debug.c index 6f12344374..09ab75af88 100644 --- a/src/util/debug.c +++ b/src/util/debug.c @@ -50,6 +50,7 @@ int debug_microseconds = SSSDBG_MICROSECONDS_UNRESOLVED; enum sss_logger_t sss_logger = STDERR_LOGGER; const char *debug_log_file = "sssd"; FILE *_sss_debug_file; +uint64_t debug_chain_id; const char *sss_logger_str[] = { [STDERR_LOGGER] = "stderr", @@ -323,7 +324,12 @@ void sss_vdebug_fn(const char *file, sss_debug_backtrace_printf(level, "[%s] [%s] (%#.4x): ", debug_prg_name, function, level); + if (debug_chain_id > 0) { + sss_debug_backtrace_printf(level, "[#%lu] ", debug_chain_id); + } + sss_debug_backtrace_vprintf(level, format, ap); + if (flags & APPEND_LINE_FEED) { sss_debug_backtrace_printf(level, "\n"); } diff --git a/src/util/sss_chain_id.c b/src/util/sss_chain_id.c new file mode 100644 index 0000000000..050a7bc048 --- /dev/null +++ b/src/util/sss_chain_id.c @@ -0,0 +1,155 @@ +/* + Authors: + Pavel Březina <[email protected]> + + 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 "config.h" + +#include <tevent.h> + +#ifdef BUILD_CHAIN_ID +extern uint64_t debug_chain_id; + +static void sss_chain_id_trace_fde(struct tevent_fd *fde, + enum tevent_event_trace_point point, + void *private_data) +{ + switch (point) { + case TEVENT_EVENT_TRACE_ATTACH: + /* Assign the current chain id when the event is created. */ + tevent_fd_set_tag(fde, debug_chain_id); + break; + case TEVENT_EVENT_TRACE_BEFORE_HANDLER: + /* Set the chain id when a handler is being called. */ + debug_chain_id = tevent_fd_get_tag(fde); + break; + default: + /* Do nothing. */ + break; + } +} + +static void sss_chain_id_trace_signal(struct tevent_signal *se, + enum tevent_event_trace_point point, + void *private_data) +{ + switch (point) { + case TEVENT_EVENT_TRACE_ATTACH: + /* Assign the current chain id when the event is created. */ + tevent_signal_set_tag(se, debug_chain_id); + break; + case TEVENT_EVENT_TRACE_BEFORE_HANDLER: + /* Set the chain id when a handler is being called. */ + debug_chain_id = tevent_signal_get_tag(se); + break; + default: + /* Do nothing. */ + break; + } +} + +static void sss_chain_id_trace_timer(struct tevent_timer *timer, + enum tevent_event_trace_point point, + void *private_data) +{ + switch (point) { + case TEVENT_EVENT_TRACE_ATTACH: + /* Assign the current chain id when the event is created. */ + tevent_timer_set_tag(timer, debug_chain_id); + break; + case TEVENT_EVENT_TRACE_BEFORE_HANDLER: + /* Set the chain id when a handler is being called. */ + debug_chain_id = tevent_timer_get_tag(timer); + break; + default: + /* Do nothing. */ + break; + } +} + +static void sss_chain_id_trace_immediate(struct tevent_immediate *im, + enum tevent_event_trace_point point, + void *private_data) +{ + switch (point) { + case TEVENT_EVENT_TRACE_ATTACH: + /* Assign the current chain id when the event is created. */ + tevent_immediate_set_tag(im, debug_chain_id); + break; + case TEVENT_EVENT_TRACE_BEFORE_HANDLER: + /* Set the chain id when a handler is being called. */ + debug_chain_id = tevent_immediate_get_tag(im); + break; + default: + /* Do nothing. */ + break; + } +} + +static void sss_chain_id_trace_loop(enum tevent_trace_point point, + void *private_data) +{ + switch (point) { + case TEVENT_TRACE_AFTER_LOOP_ONCE: + /* Restore chain id when we got back to the loop. */ + debug_chain_id = 0; + default: + /* Do nothing. */ + break; + } +} + +void sss_chain_id_setup(struct tevent_context *ev) +{ + tevent_set_trace_callback(ev, sss_chain_id_trace_loop, NULL); + tevent_set_trace_fd_callback(ev, sss_chain_id_trace_fde, NULL); + tevent_set_trace_signal_callback(ev, sss_chain_id_trace_signal, NULL); + tevent_set_trace_timer_callback(ev, sss_chain_id_trace_timer, NULL); + tevent_set_trace_immediate_callback(ev, sss_chain_id_trace_immediate, NULL); +} + +uint64_t sss_chain_id_set(uint64_t id) +{ + uint64_t old_id = debug_chain_id; + debug_chain_id = id; + return old_id; +} + +uint64_t sss_chain_id_get() +{ + return debug_chain_id; +} + +#else /* BUILD_CHAIN_ID not defined */ + +void sss_chain_id_setup(struct tevent_context *ev) +{ + return; +} + +uint64_t sss_chain_id_set(uint64_t id) +{ + return 0; +} + +uint64_t sss_chain_id_get(void) +{ + return 0; +} + +#endif /* BUILD_CHAIN_ID */ diff --git a/src/util/sss_chain_id.h b/src/util/sss_chain_id.h new file mode 100644 index 0000000000..38ab242e25 --- /dev/null +++ b/src/util/sss_chain_id.h @@ -0,0 +1,30 @@ +/* + Authors: + Pavel Březina <[email protected]> + + 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/>. +*/ + +#ifndef _SSS_CHAIN_ID_ +#define _SSS_CHAIN_ID_ + +#include <tevent.h> + +void sss_chain_id_setup(struct tevent_context *ev); +uint64_t sss_chain_id_set(uint64_t id); +uint64_t sss_chain_id_get(void); + +#endif /* _SSS_CHAIN_ID_ */ From c8179857e0105f611d654731b62d726aaa3890f7 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Pavel=20B=C5=99ezina?= <[email protected]> Date: Tue, 11 May 2021 14:45:26 +0200 Subject: [PATCH 2/2] debug: enable chain id in backend --- src/providers/data_provider/dp_request.c | 15 +++++- src/providers/data_provider_be.c | 3 ++ src/providers/ldap/sdap.h | 1 + src/providers/ldap/sdap_async.c | 47 ++++++++++++++----- src/providers/ldap/sdap_fd_events.c | 13 +++++ src/sbus/router/sbus_router_handler.c | 6 +++ .../cmocka/data_provider/test_dp_request.c | 8 ++-- src/util/sss_chain_id.c | 2 +- 8 files changed, 76 insertions(+), 19 deletions(-) diff --git a/src/providers/data_provider/dp_request.c b/src/providers/data_provider/dp_request.c index fd5a542c01..077b361f3c 100644 --- a/src/providers/data_provider/dp_request.c +++ b/src/providers/data_provider/dp_request.c @@ -27,6 +27,7 @@ #include "util/dlinklist.h" #include "util/util.h" #include "util/probes.h" +#include "util/sss_chain_id.h" struct dp_req { struct data_provider *provider; @@ -107,8 +108,16 @@ static errno_t dp_attach_req(struct dp_req *dp_req, uint32_t cli_id, const char *sender_name) { - /* If we run out of numbers we simply overflow. */ + /* If we run out of numbers we simply overflow. Zero is a reserved value + * in debug chain id thus we need to skip it. */ + if (provider->requests.index == 0) { + provider->requests.index = 1; + } dp_req->num = provider->requests.index++; + + /* Set the chain id for this request. */ + sss_chain_id_set(dp_req->num); + dp_req->name = talloc_asprintf(dp_req, "%s #%u", name, dp_req->num); if (dp_req->name == NULL) { return ENOMEM; @@ -216,8 +225,10 @@ file_dp_request(TALLOC_CTX *mem_ctx, dp_req_send_fn send_fn; struct dp_req *dp_req; struct be_ctx *be_ctx; + uint64_t old_chain_id; errno_t ret; + old_chain_id = sss_chain_id_get(); be_ctx = provider->be_ctx; ret = dp_req_new(mem_ctx, provider, domainname, name, cli_id, sender_name, @@ -272,6 +283,8 @@ file_dp_request(TALLOC_CTX *mem_ctx, ret = EOK; done: + /* Restore the chain id to its original value when leaving this request. */ + sss_chain_id_set(old_chain_id); return ret; } diff --git a/src/providers/data_provider_be.c b/src/providers/data_provider_be.c index 9fd4d88161..9d63b448ea 100644 --- a/src/providers/data_provider_be.c +++ b/src/providers/data_provider_be.c @@ -47,6 +47,7 @@ #include "util/child_common.h" #include "resolv/async_resolv.h" #include "sss_iface/sss_iface_async.h" +#include "util/sss_chain_id.h" #define ONLINE_CB_RETRY 3 #define ONLINE_CB_RETRY_MAX_DELAY 4 @@ -776,6 +777,8 @@ int main(int argc, const char *argv[]) return 2; } + sss_chain_id_setup(main_ctx->event_ctx); + ret = setenv(SSS_DOM_ENV, be_domain, 1); if (ret != 0) { DEBUG(SSSDBG_MINOR_FAILURE, "Setting "SSS_DOM_ENV" failed, journald " diff --git a/src/providers/ldap/sdap.h b/src/providers/ldap/sdap.h index f254b52c75..ffcbee8a5c 100644 --- a/src/providers/ldap/sdap.h +++ b/src/providers/ldap/sdap.h @@ -42,6 +42,7 @@ struct sdap_handle; struct sdap_op { struct sdap_op *prev, *next; struct sdap_handle *sh; + uint64_t chain_id; int msgid; bool done; diff --git a/src/providers/ldap/sdap_async.c b/src/providers/ldap/sdap_async.c index 947e2b4f46..7bf986fb80 100644 --- a/src/providers/ldap/sdap_async.c +++ b/src/providers/ldap/sdap_async.c @@ -24,6 +24,7 @@ #include "util/util.h" #include "util/strtonum.h" #include "util/probes.h" +#include "util/sss_chain_id.h" #include "providers/ldap/sdap_async_private.h" #define REPLY_REALLOC_INCREMENT 10 @@ -133,11 +134,34 @@ static void sdap_ldap_next_result(struct tevent_context *ev, sdap_process_result(ev, pvt); } +static struct sdap_op *sdap_get_message_op(struct sdap_handle *sh, + LDAPMessage *msg) +{ + struct sdap_op *op; + int msgid; + + msgid = ldap_msgid(msg); + if (msgid == -1) { + DEBUG(SSSDBG_OP_FAILURE, "can't fire callback, message id invalid!\n"); + return NULL; + } + + for (op = sh->ops; op; op = op->next) { + if (op->msgid == msgid) { + return op; + } + } + + return NULL; +} + static void sdap_process_result(struct tevent_context *ev, void *pvt) { struct sdap_handle *sh = talloc_get_type(pvt, struct sdap_handle); + uint64_t old_chain_id = sss_chain_id_get(); struct timeval no_timeout = {0, 0}; struct tevent_timer *te; + struct sdap_op *op; LDAPMessage *msg; int ret; @@ -167,6 +191,12 @@ static void sdap_process_result(struct tevent_context *ev, void *pvt) return; } + /* Set the chain id if we can match the operation. */ + op = sdap_get_message_op(sh, msg); + if (op != NULL) { + sss_chain_id_set(op->chain_id); + } + /* We don't know if this will be the last result. * * important: we must do this before actually processing the message @@ -183,6 +213,7 @@ static void sdap_process_result(struct tevent_context *ev, void *pvt) /* now process this message */ sdap_process_message(ev, sh, msg); + sss_chain_id_set(old_chain_id); } static const char *sdap_ldap_result_str(int msgtype) @@ -250,27 +281,16 @@ static void sdap_process_message(struct tevent_context *ev, { struct sdap_msg *reply; struct sdap_op *op; - int msgid; int msgtype; int ret; - msgid = ldap_msgid(msg); - if (msgid == -1) { - DEBUG(SSSDBG_OP_FAILURE, "can't fire callback, message id invalid!\n"); - ldap_msgfree(msg); - return; - } - msgtype = ldap_msgtype(msg); - for (op = sh->ops; op; op = op->next) { - if (op->msgid == msgid) break; - } - + op = sdap_get_message_op(sh, msg); if (op == NULL) { DEBUG(SSSDBG_OP_FAILURE, "Unmatched msgid, discarding message (type: %0x)\n", - msgtype); + msgtype); ldap_msgfree(msg); return; } @@ -438,6 +458,7 @@ int sdap_op_add(TALLOC_CTX *memctx, struct tevent_context *ev, op->callback = callback; op->data = data; op->ev = ev; + op->chain_id = sss_chain_id_get(); DEBUG(SSSDBG_TRACE_INTERNAL, "New operation %d timeout %d\n", op->msgid, timeout); diff --git a/src/providers/ldap/sdap_fd_events.c b/src/providers/ldap/sdap_fd_events.c index 17082e26a3..42b2efe260 100644 --- a/src/providers/ldap/sdap_fd_events.c +++ b/src/providers/ldap/sdap_fd_events.c @@ -24,6 +24,7 @@ #include "util/util.h" #include "util/sss_sockets.h" +#include "util/sss_chain_id.h" #include "providers/ldap/sdap_async_private.h" struct sdap_fd_events { @@ -89,6 +90,7 @@ static int sdap_ldap_connect_callback_add(LDAP *ld, Sockbuf *sb, { int ret; ber_socket_t ber_fd; + uint64_t old_chain_id; struct timeval *tv = NULL; struct fd_event_item *fd_event_item; struct ldap_cb_data *cb_data = talloc_get_type(ctx->lc_arg, @@ -139,9 +141,14 @@ static int sdap_ldap_connect_callback_add(LDAP *ld, Sockbuf *sb, return ENOMEM; } + /* This is a global event which is shared between multiple requests. However + * it is usually created from an input request chain therefore we need to set + * the chain id to zero explicitly. */ + old_chain_id = sss_chain_id_set(0); fd_event_item->fde = tevent_add_fd(cb_data->ev, fd_event_item, ber_fd, TEVENT_FD_READ, sdap_ldap_result, cb_data->sh); + sss_chain_id_set(old_chain_id); if (fd_event_item->fde == NULL) { DEBUG(SSSDBG_CRIT_FAILURE, "tevent_add_fd failed.\n"); talloc_free(fd_event_item); @@ -195,6 +202,7 @@ static void sdap_ldap_connect_callback_del(LDAP *ld, Sockbuf *sb, static int sdap_install_ldap_callbacks(struct sdap_handle *sh, struct tevent_context *ev) { + uint64_t old_chain_id; int fd; int ret; @@ -214,9 +222,14 @@ static int sdap_install_ldap_callbacks(struct sdap_handle *sh, ret = get_fd_from_ldap(sh->ldap, &fd); if (ret) return ret; + /* This is a global event which is shared between multiple requests. However + * it is usually created from an input request chain therefore we need to set + * the chain id to zero explicitly. */ + old_chain_id = sss_chain_id_set(0); sh->sdap_fd_events->fde = tevent_add_fd(ev, sh->sdap_fd_events, fd, TEVENT_FD_READ, sdap_ldap_result, sh); + sss_chain_id_set(old_chain_id); if (!sh->sdap_fd_events->fde) { talloc_zfree(sh->sdap_fd_events); return ENOMEM; diff --git a/src/sbus/router/sbus_router_handler.c b/src/sbus/router/sbus_router_handler.c index 9420400054..c7776060f6 100644 --- a/src/sbus/router/sbus_router_handler.c +++ b/src/sbus/router/sbus_router_handler.c @@ -26,6 +26,7 @@ #include "util/util.h" #include "util/dlinklist.h" +#include "util/sss_chain_id.h" #include "sbus/sbus_private.h" struct sbus_message_meta { @@ -127,6 +128,11 @@ static void sbus_issue_request_done(struct tevent_req *subreq) DBusMessage *reply; errno_t ret; + /* This is a top level request. It can reply to more then one dp request + * therefore we need to set the id to 0 since it is not known at this + * moment. */ + sss_chain_id_set(0); + state = tevent_req_callback_data(subreq, struct sbus_issue_request_state); sbus_message_meta_read(state->message, &meta); diff --git a/src/tests/cmocka/data_provider/test_dp_request.c b/src/tests/cmocka/data_provider/test_dp_request.c index dfd8951a40..a590ae51df 100644 --- a/src/tests/cmocka/data_provider/test_dp_request.c +++ b/src/tests/cmocka/data_provider/test_dp_request.c @@ -231,7 +231,7 @@ static void test_get_name_by_uid(void **state) SENDER_NAME, DPT_ID, DPM_ACCOUNT_HANDLER, 0, req_data, &req_name); assert_non_null(req); - assert_string_equal(req_name, REQ_NAME" #0"); + assert_string_equal(req_name, REQ_NAME" #1"); talloc_zfree(req_name); /* Send request #2 */ @@ -239,7 +239,7 @@ static void test_get_name_by_uid(void **state) SENDER_NAME, DPT_ID, DPM_ACCOUNT_HANDLER, 0, req_data2, &req_name); assert_non_null(req2); - assert_string_equal(req_name, REQ_NAME" #1"); + assert_string_equal(req_name, REQ_NAME" #2"); talloc_zfree(req_name); /* Send request #3 */ @@ -247,7 +247,7 @@ static void test_get_name_by_uid(void **state) SENDER_NAME, DPT_ID, DPM_ACCOUNT_HANDLER, 0, req_data3, &req_name); assert_non_null(req3); - assert_string_equal(req_name, REQ_NAME" #2"); + assert_string_equal(req_name, REQ_NAME" #3"); talloc_zfree(req_name); tevent_loop_wait(test_ctx->tctx->ev); @@ -305,7 +305,7 @@ static void test_type_mismatch(void **state) req = dp_req_send(test_ctx, test_ctx->provider, NULL, REQ_NAME, CID, SENDER_NAME, DPT_ID, DPM_ACCOUNT_HANDLER, 0, req_data, &req_name); assert_non_null(req); - assert_string_equal(req_name, REQ_NAME" #0"); + assert_string_equal(req_name, REQ_NAME" #1"); talloc_zfree(req_name); tevent_loop_wait(test_ctx->tctx->ev); diff --git a/src/util/sss_chain_id.c b/src/util/sss_chain_id.c index 050a7bc048..478b845557 100644 --- a/src/util/sss_chain_id.c +++ b/src/util/sss_chain_id.c @@ -130,7 +130,7 @@ uint64_t sss_chain_id_set(uint64_t id) return old_id; } -uint64_t sss_chain_id_get() +uint64_t sss_chain_id_get(void) { return debug_chain_id; }
_______________________________________________ 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
