URL: https://github.com/SSSD/sssd/pull/5863
Author: justin-stephenson
 Title: #5863: Responder and Child process tevent chain id improvements
Action: synchronized

To pull the PR as Git branch:
git remote add ghsssd https://github.com/SSSD/sssd
git fetch ghsssd pull/5863/head:pr5863
git checkout pr5863
From b0a413efc48994c0fd0f01055c8158cdfcb14856 Mon Sep 17 00:00:00 2001
From: Justin Stephenson <jstep...@redhat.com>
Date: Wed, 10 Nov 2021 15:41:23 +0000
Subject: [PATCH 01/11] util: Split chain ID tevent functions

Commonly used chain ID functions sss_chain_id_get() and
sss_chain_id_set() will be isolated from requiring
tevent when building sources.
---
 Makefile.am                      |   2 +
 src/providers/data_provider_be.c |   1 +
 src/util/sss_chain_id.c          | 130 +----------------------------
 src/util/sss_chain_id.h          |   7 +-
 src/util/sss_chain_id_tevent.c   | 138 +++++++++++++++++++++++++++++++
 src/util/sss_chain_id_tevent.h   |  29 +++++++
 6 files changed, 175 insertions(+), 132 deletions(-)
 create mode 100644 src/util/sss_chain_id_tevent.c
 create mode 100644 src/util/sss_chain_id_tevent.h

diff --git a/Makefile.am b/Makefile.am
index f6bc9414d0..5174eba05a 100644
--- a/Makefile.am
+++ b/Makefile.am
@@ -684,6 +684,7 @@ dist_noinst_HEADERS = \
     src/util/session_recording.h \
     src/util/strtonum.h \
     src/util/sss_cli_cmd.h \
+    src/util/sss_chain_id_tevent.h \
     src/util/sss_chain_id.h \
     src/util/sss_ptr_hash.h \
     src/util/sss_ptr_list.h \
@@ -1264,6 +1265,7 @@ libsss_util_la_SOURCES = \
     src/util/files.c \
     src/util/selinux.c \
     src/util/sss_regexp.c \
+    src/util/sss_chain_id_tevent.c \
     src/util/sss_chain_id.c \
     $(NULL)
 libsss_util_la_CFLAGS = \
diff --git a/src/providers/data_provider_be.c b/src/providers/data_provider_be.c
index 9d63b448ea..c632ec9461 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_tevent.h"
 #include "util/sss_chain_id.h"
 
 #define ONLINE_CB_RETRY 3
diff --git a/src/util/sss_chain_id.c b/src/util/sss_chain_id.c
index f892e2eb78..db312698ab 100644
--- a/src/util/sss_chain_id.c
+++ b/src/util/sss_chain_id.c
@@ -18,115 +18,8 @@
     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:
-        /* Reset chain id when we got back to the loop. An event handler
-         * that set chain id was fired. This tracepoint represents a place
-         * after the event handler was finished, we need to restore chain
-         * id to 0 (out of request).
-         */
-        debug_chain_id = 0;
-        break;
-    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);
-}
+#include <stdint.h>
+#include "util/sss_chain_id.h"
 
 uint64_t sss_chain_id_set(uint64_t id)
 {
@@ -139,22 +32,3 @@ uint64_t sss_chain_id_get(void)
 {
     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
index b29fad0cb1..e15cc5b889 100644
--- a/src/util/sss_chain_id.h
+++ b/src/util/sss_chain_id.h
@@ -1,6 +1,6 @@
 /*
     Authors:
-        Pavel Březina <pbrez...@redhat.com>
+        Justin Stephenson <jstep...@redhat.com>
 
     Copyright (C) 2021 Red Hat
 
@@ -21,10 +21,9 @@
 #ifndef _SSS_CHAIN_ID_
 #define _SSS_CHAIN_ID_
 
-#include <tevent.h>
+#include <stdint.h>
 
-/* Setup chain id tracking on tevent context. */
-void sss_chain_id_setup(struct tevent_context *ev);
+extern uint64_t debug_chain_id;
 
 /* Explicitly set new chain id. The old id is returned. */
 uint64_t sss_chain_id_set(uint64_t id);
diff --git a/src/util/sss_chain_id_tevent.c b/src/util/sss_chain_id_tevent.c
new file mode 100644
index 0000000000..a68607da65
--- /dev/null
+++ b/src/util/sss_chain_id_tevent.c
@@ -0,0 +1,138 @@
+/*
+    Authors:
+        Pavel Březina <pbrez...@redhat.com>
+
+    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 "util/sss_chain_id.h"
+
+#include <tevent.h>
+
+#ifdef BUILD_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:
+        /* Reset chain id when we got back to the loop. An event handler
+         * that set chain id was fired. This tracepoint represents a place
+         * after the event handler was finished, we need to restore chain
+         * id to 0 (out of request).
+         */
+        debug_chain_id = 0;
+        break;
+    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);
+}
+
+#else /* BUILD_CHAIN_ID not defined */
+
+void sss_chain_id_setup(struct tevent_context *ev)
+{
+    return;
+}
+
+#endif /* BUILD_CHAIN_ID */
diff --git a/src/util/sss_chain_id_tevent.h b/src/util/sss_chain_id_tevent.h
new file mode 100644
index 0000000000..547d271641
--- /dev/null
+++ b/src/util/sss_chain_id_tevent.h
@@ -0,0 +1,29 @@
+/*
+    Authors:
+        Pavel Březina <pbrez...@redhat.com>
+
+    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_TEVENT_
+#define _SSS_CHAIN_ID_TEVENT_
+
+#include <tevent.h>
+
+/* Setup chain id tracking on tevent context. */
+void sss_chain_id_setup(struct tevent_context *ev);
+
+#endif /* _SSS_CHAIN_ID_TEVENT_ */

From 736643fd1e0ed9f74adec9df07ed18381b1746df Mon Sep 17 00:00:00 2001
From: Justin Stephenson <jstep...@redhat.com>
Date: Thu, 28 Oct 2021 13:48:24 +0000
Subject: [PATCH 02/11] RESPONDER: Remove extraneous client ID logging

Prevent duplicate ID logging. ID will be logged in separate commit
with added tevent chain ID support in responders.
---
 src/responder/common/responder_common.c |  4 ++--
 src/responder/nss/nss_get_object.c      |  5 ++---
 src/responder/pam/pamsrv_cmd.c          |  4 ++--
 src/responder/pam/pamsrv_dp.c           |  9 ++++----
 src/util/sss_pam_data.c                 | 28 ++++++++++++-------------
 5 files changed, 23 insertions(+), 27 deletions(-)

diff --git a/src/responder/common/responder_common.c b/src/responder/common/responder_common.c
index 913dbcd800..da37222be8 100644
--- a/src/responder/common/responder_common.c
+++ b/src/responder/common/responder_common.c
@@ -639,8 +639,8 @@ static void accept_fd_handler(struct tevent_context *ev,
 
     rctx->client_id_num++;
     DEBUG(SSSDBG_TRACE_FUNC,
-          "Client [CID #%u][cmd %s][uid %u][%p][%d] connected%s!\n",
-          rctx->client_id_num, cctx->cmd_line, cli_creds_get_uid(cctx->creds),
+          "Client [cmd %s][uid %u][%p][%d] connected%s!\n",
+          cctx->cmd_line, cli_creds_get_uid(cctx->creds),
           cctx, cctx->cfd, accept_ctx->is_private ? " to privileged pipe" : "");
 
     return;
diff --git a/src/responder/nss/nss_get_object.c b/src/responder/nss/nss_get_object.c
index 9d53f070c9..30d8cb7e15 100644
--- a/src/responder/nss/nss_get_object.c
+++ b/src/responder/nss/nss_get_object.c
@@ -309,9 +309,8 @@ nss_get_object_send(TALLOC_CTX *mem_ctx,
         goto done;
     }
 
-    DEBUG(SSSDBG_TRACE_FUNC, "Client [%p][%d][CID #%u]: sent cache request #%u\n",
-          cli_ctx, cli_ctx->cfd, cli_ctx->rctx->client_id_num,
-          cache_req_get_reqid(subreq));
+    DEBUG(SSSDBG_TRACE_FUNC, "Client [%p][%d]: sent cache request #%u\n",
+          cli_ctx, cli_ctx->cfd, cache_req_get_reqid(subreq));
 
     tevent_req_set_callback(subreq, nss_get_object_done, req);
 
diff --git a/src/responder/pam/pamsrv_cmd.c b/src/responder/pam/pamsrv_cmd.c
index 20c332b1a4..ad64ca7d20 100644
--- a/src/responder/pam/pamsrv_cmd.c
+++ b/src/responder/pam/pamsrv_cmd.c
@@ -1154,8 +1154,8 @@ static void pam_reply(struct pam_auth_req *preq)
     }
 
 done:
-    DEBUG(SSSDBG_FUNC_DATA, "Returning [%d]: %s to the client [CID #%u]\n",
-          pd->pam_status, pam_strerror(NULL, pd->pam_status), pd->client_id_num);
+    DEBUG(SSSDBG_FUNC_DATA, "[CID #%u] Returning [%d]: %s to the client\n",
+          pd->client_id_num, pd->pam_status, pam_strerror(NULL, pd->pam_status));
     sss_cmd_done(cctx, preq);
 }
 
diff --git a/src/responder/pam/pamsrv_dp.c b/src/responder/pam/pamsrv_dp.c
index b3900e17e9..24bda2c658 100644
--- a/src/responder/pam/pamsrv_dp.c
+++ b/src/responder/pam/pamsrv_dp.c
@@ -47,8 +47,7 @@ pam_dp_send_req(struct pam_auth_req *preq)
         return EIO;
     }
 
-    DEBUG(SSSDBG_CONF_SETTINGS, "Sending request [CID #%u] with the following data:\n",
-                                preq->client_id_num);
+    DEBUG(SSSDBG_CONF_SETTINGS, "Sending request with the following data:\n");
     DEBUG_PAM_DATA(SSSDBG_CONF_SETTINGS, preq->pd);
 
     subreq = sbus_call_dp_dp_pamHandler_send(preq, be_conn->conn,
@@ -85,11 +84,11 @@ pam_dp_send_req_done(struct tevent_req *subreq)
     preq->pd->pam_status = pam_response->pam_status;
     preq->pd->account_locked = pam_response->account_locked;
 
-    DEBUG(SSSDBG_FUNC_DATA, "received: [%d (%s)][%s][CID #%u]\n",
+    DEBUG(SSSDBG_FUNC_DATA, "[CID #%u] received: [%d (%s)][%s]\n",
+          preq->pd->client_id_num,
           pam_response->pam_status,
           pam_strerror(NULL, pam_response->pam_status),
-          preq->pd->domain,
-          preq->pd->client_id_num);
+          preq->pd->domain);
 
     for (resp = pam_response->resp_list; resp != NULL; resp = resp->next) {
         talloc_steal(preq->pd, resp);
diff --git a/src/util/sss_pam_data.c b/src/util/sss_pam_data.c
index ebea11ea59..3eda598c68 100644
--- a/src/util/sss_pam_data.c
+++ b/src/util/sss_pam_data.c
@@ -165,25 +165,23 @@ errno_t copy_pam_data(TALLOC_CTX *mem_ctx, struct pam_data *src,
 
 void pam_print_data(int l, struct pam_data *pd)
 {
-    DEBUG(l, "[CID #%u] command: %s\n", pd->client_id_num, sss_cmd2str(pd->cmd));
-    DEBUG(l, "[CID #%u] domain: %s\n", pd->client_id_num, PAM_SAFE_ITEM(pd->domain));
-    DEBUG(l, "[CID #%u] user: %s\n", pd->client_id_num, PAM_SAFE_ITEM(pd->user));
-    DEBUG(l, "[CID #%u] service: %s\n", pd->client_id_num, PAM_SAFE_ITEM(pd->service));
-    DEBUG(l, "[CID #%u] tty: %s\n", pd->client_id_num, PAM_SAFE_ITEM(pd->tty));
-    DEBUG(l, "[CID #%u] ruser: %s\n", pd->client_id_num, PAM_SAFE_ITEM(pd->ruser));
-    DEBUG(l, "[CID #%u] rhost: %s\n", pd->client_id_num, PAM_SAFE_ITEM(pd->rhost));
-    DEBUG(l, "[CID #%u] authtok type: %d (%s)\n",
-          pd->client_id_num,
+    DEBUG(l, "command: %s\n", sss_cmd2str(pd->cmd));
+    DEBUG(l, "domain: %s\n", PAM_SAFE_ITEM(pd->domain));
+    DEBUG(l, "user: %s\n", PAM_SAFE_ITEM(pd->user));
+    DEBUG(l, "service: %s\n", PAM_SAFE_ITEM(pd->service));
+    DEBUG(l, "tty: %s\n", PAM_SAFE_ITEM(pd->tty));
+    DEBUG(l, "ruser: %s\n", PAM_SAFE_ITEM(pd->ruser));
+    DEBUG(l, "rhost: %s\n", PAM_SAFE_ITEM(pd->rhost));
+    DEBUG(l, "authtok type: %d (%s)\n",
           sss_authtok_get_type(pd->authtok),
           sss_authtok_type_to_str(sss_authtok_get_type(pd->authtok)));
-    DEBUG(l, "[CID #%u] newauthtok type: %d (%s)\n",
-          pd->client_id_num,
+    DEBUG(l, "newauthtok type: %d (%s)\n",
           sss_authtok_get_type(pd->newauthtok),
           sss_authtok_type_to_str(sss_authtok_get_type(pd->newauthtok)));
-    DEBUG(l, "[CID #%u] priv: %d\n", pd->client_id_num, pd->priv);
-    DEBUG(l, "[CID #%u] cli_pid: %d\n", pd->client_id_num, pd->cli_pid);
-    DEBUG(l, "[CID #%u] logon name: %s\n", pd->client_id_num, PAM_SAFE_ITEM(pd->logon_name));
-    DEBUG(l, "[CID #%u] flags: %d\n", pd->client_id_num, pd->cli_flags);
+    DEBUG(l, "priv: %d\n", pd->priv);
+    DEBUG(l, "cli_pid: %d\n", pd->cli_pid);
+    DEBUG(l, "logon name: %s\n", PAM_SAFE_ITEM(pd->logon_name));
+    DEBUG(l, "flags: %d\n", pd->cli_flags);
 }
 
 int pam_add_response(struct pam_data *pd, enum response_type type,

From cc7e2a30d234cf7a1976b6aa2faa2a8dfd462736 Mon Sep 17 00:00:00 2001
From: Justin Stephenson <jstep...@redhat.com>
Date: Mon, 25 Oct 2021 16:19:04 +0000
Subject: [PATCH 03/11] RESPONDER: Support chain ID logging

---
 .../common/cache_req/cache_req_search.c          | 16 ++++++++++++++++
 src/responder/common/responder.h                 |  1 +
 src/responder/common/responder_common.c          | 12 +++++++++++-
 3 files changed, 28 insertions(+), 1 deletion(-)

diff --git a/src/responder/common/cache_req/cache_req_search.c b/src/responder/common/cache_req/cache_req_search.c
index a3e25adbd2..c5c6ccff6a 100644
--- a/src/responder/common/cache_req/cache_req_search.c
+++ b/src/responder/common/cache_req/cache_req_search.c
@@ -26,6 +26,7 @@
 #include "responder/common/cache_req/cache_req_private.h"
 #include "responder/common/cache_req/cache_req_plugin.h"
 #include "db/sysdb.h"
+#include "util/sss_chain_id.h"
 
 static errno_t cache_req_search_ncache(struct cache_req *cr)
 {
@@ -282,6 +283,7 @@ cache_req_expiration_status(struct cache_req *cr,
 }
 
 struct cache_req_search_state {
+    uint64_t chain_id;
     /* input data */
     struct tevent_context *ev;
     struct resp_ctx *rctx;
@@ -420,6 +422,11 @@ static errno_t cache_req_search_dp(struct tevent_req *req,
 
     state = tevent_req_data(req, struct cache_req_search_state);
 
+    /* store the global chain ID and set it back in callback.
+     * Otherwise we lose the chain ID when dp_send_fn is called
+     * (chain ID is set to 0 in sbus_issue_request_done). */
+    state->chain_id = sss_chain_id_get();
+
     switch (status) {
     case CACHE_OBJECT_MIDPOINT:
         /* Out of band update. The calling function will return the cached
@@ -495,6 +502,8 @@ static void cache_req_search_done(struct tevent_req *subreq)
     state->dp_success = state->cr->plugin->dp_recv_fn(subreq, state->cr);
     talloc_zfree(subreq);
 
+    sss_chain_id_set(state->chain_id);
+
     /* Do not try to read from cache if the domain is inconsistent */
     if (sss_domain_get_state(state->cr->domain) == DOM_INCONSISTENT) {
         CACHE_REQ_DEBUG(SSSDBG_TRACE_FUNC, state->cr, "Domain inconsistent, "
@@ -557,6 +566,7 @@ struct cache_req_locate_domain_state {
     struct cache_req *cr;
 
     char *found_domain;
+    uint64_t chain_id;
 };
 
 static void cache_req_locate_domain_done(struct tevent_req *subreq);
@@ -578,6 +588,11 @@ struct tevent_req *cache_req_locate_domain_send(TALLOC_CTX *mem_ctx,
     }
     state->cr = cr;
 
+    /* store the global chain ID and set it back in callback.
+     * Otherwise we lose the chain ID when dp_get_domain_check_fn is called
+     * (chain ID is set to 0 in sbus_issue_request_done). */
+    state->chain_id = sss_chain_id_get();
+
     should_run = cr->plugin->dp_get_domain_check_fn(cr->rctx,
                                                     get_domains_head(cr->domain),
                                                     cr->data);
@@ -624,6 +639,7 @@ static void cache_req_locate_domain_done(struct tevent_req *subreq)
                                                    state->cr,
                                                    &state->found_domain);
     talloc_zfree(subreq);
+    sss_chain_id_set(state->chain_id);
     if (ret != EOK) {
         tevent_req_error(req, ret);
         return;
diff --git a/src/responder/common/responder.h b/src/responder/common/responder.h
index 90575b89e7..5cb79e3e63 100644
--- a/src/responder/common/responder.h
+++ b/src/responder/common/responder.h
@@ -165,6 +165,7 @@ struct cli_ctx {
 
     struct cli_creds *creds;
     char *cmd_line;
+    uint64_t old_chain_id;
 
     void *protocol_ctx;
     void *state_ctx;
diff --git a/src/responder/common/responder_common.c b/src/responder/common/responder_common.c
index da37222be8..2c2bd4a234 100644
--- a/src/responder/common/responder_common.c
+++ b/src/responder/common/responder_common.c
@@ -42,6 +42,8 @@
 #include "providers/data_provider.h"
 #include "util/util_creds.h"
 #include "sss_iface/sss_iface_async.h"
+#include "util/sss_chain_id_tevent.h"
+#include "util/sss_chain_id.h"
 
 #ifdef HAVE_SYSTEMD
 #include <systemd/sd-daemon.h>
@@ -85,6 +87,8 @@ static void client_close_fn(struct tevent_context *ev,
               "Failed to close fd [%d]: [%s]\n",
                ctx->cfd, strerror(ret));
     }
+    /* Restore the original chain id  */
+    sss_chain_id_set(ctx->old_chain_id);
 
     DEBUG(SSSDBG_TRACE_INTERNAL,
           "Terminated client [%p][%d]\n",
@@ -521,6 +525,8 @@ static void accept_fd_handler(struct tevent_context *ev,
     int ret;
     int fd = accept_ctx->is_private ? rctx->priv_lfd : rctx->lfd;
 
+    rctx->client_id_num++;
+
     if (accept_ctx->is_private) {
         ret = stat(rctx->priv_sock_name, &stat_buf);
         if (ret == -1) {
@@ -549,6 +555,9 @@ static void accept_fd_handler(struct tevent_context *ev,
         return;
     }
 
+    /* Set the chain id */
+    cctx->old_chain_id = sss_chain_id_set(rctx->client_id_num);
+
     talloc_set_destructor(cctx, cli_ctx_destructor);
 
     len = sizeof(cctx->addr);
@@ -637,7 +646,6 @@ static void accept_fd_handler(struct tevent_context *ev,
         /* Non-fatal, continue */
     }
 
-    rctx->client_id_num++;
     DEBUG(SSSDBG_TRACE_FUNC,
           "Client [cmd %s][uid %u][%p][%d] connected%s!\n",
           cctx->cmd_line, cli_creds_get_uid(cctx->creds),
@@ -1311,6 +1319,8 @@ int sss_process_init(TALLOC_CTX *mem_ctx,
         goto fail;
     }
 
+    sss_chain_id_setup(rctx->ev);
+
     /* Ensure that the client timeout is at least ten seconds */
     if (rctx->client_idle_timeout < 10) {
         rctx->client_idle_timeout = 10;

From 36ac0f3be5f42f68b6d50debfb2414b20ac3e3e2 Mon Sep 17 00:00:00 2001
From: Justin Stephenson <jstep...@redhat.com>
Date: Wed, 3 Nov 2021 19:33:17 +0000
Subject: [PATCH 04/11] DEBUG: Log chain ID messages with [CID#X] tag

Inform the debug module when a responder process is sending debug
log messages, use the [CID #] tag in responder code and [RID #]
tag in backend/child process code.
---
 src/responder/common/responder_common.c |  2 ++
 src/util/debug.c                        | 14 ++++++++++----
 src/util/debug.h                        |  1 +
 src/util/server.c                       |  3 +++
 4 files changed, 16 insertions(+), 4 deletions(-)

diff --git a/src/responder/common/responder_common.c b/src/responder/common/responder_common.c
index 2c2bd4a234..9087f1cfc7 100644
--- a/src/responder/common/responder_common.c
+++ b/src/responder/common/responder_common.c
@@ -1321,6 +1321,8 @@ int sss_process_init(TALLOC_CTX *mem_ctx,
 
     sss_chain_id_setup(rctx->ev);
 
+    debug_from_responder = true;
+
     /* Ensure that the client timeout is at least ten seconds */
     if (rctx->client_idle_timeout < 10) {
         rctx->client_idle_timeout = 10;
diff --git a/src/util/debug.c b/src/util/debug.c
index 9531237183..8f0ca93b87 100644
--- a/src/util/debug.c
+++ b/src/util/debug.c
@@ -36,7 +36,8 @@
 
 #include "util/util.h"
 
-#define DEBUG_CHAIN_ID_FMT "[RID#%lu] "
+#define DEBUG_CHAIN_ID_FMT_RID "[RID#%lu] "
+#define DEBUG_CHAIN_ID_FMT_CID "[CID#%lu] "
 
 /* from debug_backtrace.h */
 void sss_debug_backtrace_init(void);
@@ -45,6 +46,7 @@ void sss_debug_backtrace_printf(int level, const char *format, ...);
 void sss_debug_backtrace_endmsg(const char *file, long line, int level);
 
 const char *debug_prg_name = "sssd";
+bool debug_from_responder;
 
 int debug_level = SSSDBG_UNRESOLVED;
 int debug_timestamps = SSSDBG_TIMESTAMP_UNRESOLVED;
@@ -295,12 +297,12 @@ void sss_vdebug_fn(const char *file,
         if (debug_chain_id > 0) {
             result_fmt = chain_id_fmt_fixed;
             ret = snprintf(chain_id_fmt_fixed, sizeof(chain_id_fmt_fixed),
-                           DEBUG_CHAIN_ID_FMT"%s", debug_chain_id, format);
+                           DEBUG_CHAIN_ID_FMT_RID"%s", debug_chain_id, format);
             if (ret < 0) {
                 va_end(ap_fallback);
                 return;
             } else if (ret >= sizeof(chain_id_fmt_fixed)) {
-                ret = asprintf(&chain_id_fmt_dyn, DEBUG_CHAIN_ID_FMT"%s",
+                ret = asprintf(&chain_id_fmt_dyn, DEBUG_CHAIN_ID_FMT_RID"%s",
                                debug_chain_id, format);
                 if (ret < 0) {
                     va_end(ap_fallback);
@@ -351,7 +353,11 @@ void sss_vdebug_fn(const char *file,
                                debug_prg_name, function, level);
 
     if (debug_chain_id > 0) {
-        sss_debug_backtrace_printf(level, DEBUG_CHAIN_ID_FMT, debug_chain_id);
+        if (debug_from_responder) {
+            sss_debug_backtrace_printf(level, DEBUG_CHAIN_ID_FMT_CID, debug_chain_id);
+        } else {
+            sss_debug_backtrace_printf(level, DEBUG_CHAIN_ID_FMT_RID, debug_chain_id);
+        }
     }
 
     sss_debug_backtrace_vprintf(level, format, ap);
diff --git a/src/util/debug.h b/src/util/debug.h
index 01713cb35b..735c2b2a12 100644
--- a/src/util/debug.h
+++ b/src/util/debug.h
@@ -50,6 +50,7 @@ enum sss_logger_t {
 
 extern const char *sss_logger_str[]; /* mapping: sss_logger_t -> string */
 extern const char *debug_prg_name;
+extern bool debug_from_responder;
 extern int debug_level;
 extern int debug_timestamps;
 extern int debug_microseconds;
diff --git a/src/util/server.c b/src/util/server.c
index e3133a61dd..8eca366c1d 100644
--- a/src/util/server.c
+++ b/src/util/server.c
@@ -484,6 +484,9 @@ int server_setup(const char *name, int flags,
         return ENOMEM;
     }
 
+    /* Responders will overide this default */
+    debug_from_responder = false;
+
     my_pid = getpid();
     ret = setpgid(my_pid, my_pid);
     if (ret != EOK) {

From fbd0fc34b0afde3fd2b60d21cb3c74e892e623e4 Mon Sep 17 00:00:00 2001
From: Justin Stephenson <jstep...@redhat.com>
Date: Wed, 10 Nov 2021 16:39:07 +0000
Subject: [PATCH 05/11] krb5_child: Add chain ID logging support

---
 Makefile.am                             |  1 +
 src/providers/krb5/krb5_auth.h          |  1 +
 src/providers/krb5/krb5_child.c         |  8 ++++++++
 src/providers/krb5/krb5_child_handler.c | 15 +++++++++++++++
 4 files changed, 25 insertions(+)

diff --git a/Makefile.am b/Makefile.am
index 5174eba05a..490764c49a 100644
--- a/Makefile.am
+++ b/Makefile.am
@@ -4509,6 +4509,7 @@ krb5_child_SOURCES = \
     src/util/util.c \
     src/util/util_ext.c \
     src/util/signal.c \
+    src/util/sss_chain_id.c \
     src/util/strtonum.c \
     src/util/become_user.c \
     src/util/util_errors.c \
diff --git a/src/providers/krb5/krb5_auth.h b/src/providers/krb5/krb5_auth.h
index c706625f6f..575bc0f0bc 100644
--- a/src/providers/krb5/krb5_auth.h
+++ b/src/providers/krb5/krb5_auth.h
@@ -47,6 +47,7 @@
 #define CHILD_OPT_FAST_PRINCIPAL "fast-principal"
 #define CHILD_OPT_CANONICALIZE "canonicalize"
 #define CHILD_OPT_SSS_CREDS_PASSWORD "sss-creds-password"
+#define CHILD_OPT_CHAIN_ID "chain-id"
 
 struct krb5child_req {
     struct pam_data *pd;
diff --git a/src/providers/krb5/krb5_child.c b/src/providers/krb5/krb5_child.c
index 594c86bf61..671e49ee93 100644
--- a/src/providers/krb5/krb5_child.c
+++ b/src/providers/krb5/krb5_child.c
@@ -36,6 +36,7 @@
 #include "util/user_info_msg.h"
 #include "util/child_common.h"
 #include "util/find_uid.h"
+#include "util/sss_chain_id.h"
 #include "src/util/util_errors.h"
 #include "providers/backend.h"
 #include "providers/krb5/krb5_auth.h"
@@ -3317,6 +3318,7 @@ int main(int argc, const char *argv[])
     krb5_error_code kerr;
     uid_t fast_uid = 0;
     gid_t fast_gid = 0;
+    uint64_t chain_id = 0;
     struct cli_opts cli_opts = { 0 };
     int sss_creds_password = 0;
 
@@ -3345,6 +3347,8 @@ int main(int argc, const char *argv[])
          _("Requests canonicalization of the principal name"), NULL},
         {CHILD_OPT_SSS_CREDS_PASSWORD, 0, POPT_ARG_NONE, &sss_creds_password,
          0, _("Use custom version of krb5_get_init_creds_password"), NULL},
+        {CHILD_OPT_CHAIN_ID, 0, POPT_ARG_LONG, &chain_id,
+         0, _("Tevent chain ID used for logging purposes"), NULL},
         POPT_TABLEEND
     };
 
@@ -3386,6 +3390,10 @@ int main(int argc, const char *argv[])
         }
     }
 
+    if (chain_id > 0) {
+        sss_chain_id_set(chain_id);
+    }
+
     DEBUG_INIT(debug_level, opt_logger);
 
     DEBUG(SSSDBG_TRACE_FUNC, "krb5_child started.\n");
diff --git a/src/providers/krb5/krb5_child_handler.c b/src/providers/krb5/krb5_child_handler.c
index 778e38fc8e..43e39ca581 100644
--- a/src/providers/krb5/krb5_child_handler.c
+++ b/src/providers/krb5/krb5_child_handler.c
@@ -26,6 +26,7 @@
 
 #include "util/util.h"
 #include "util/child_common.h"
+#include "util/sss_chain_id.h"
 #include "providers/krb5/krb5_common.h"
 #include "providers/krb5/krb5_auth.h"
 #include "src/providers/krb5/krb5_utils.h"
@@ -301,6 +302,7 @@ errno_t set_extra_args(TALLOC_CTX *mem_ctx, struct krb5_ctx *krb5_ctx,
 {
     const char **extra_args;
     const char *krb5_realm;
+    uint64_t chain_id;
     size_t c = 0;
     int ret;
 
@@ -418,6 +420,19 @@ errno_t set_extra_args(TALLOC_CTX *mem_ctx, struct krb5_ctx *krb5_ctx,
         c++;
     }
 
+    chain_id = sss_chain_id_get();
+    if (chain_id > 0) {
+        extra_args[c] = talloc_asprintf(extra_args,
+                                        "--"CHILD_OPT_CHAIN_ID"=%lu",
+                                        chain_id);
+        if (extra_args[c] == NULL) {
+            DEBUG(SSSDBG_OP_FAILURE, "talloc_asprintf failed.\n");
+            ret = ENOMEM;
+            goto done;
+        }
+    }
+    c++;
+
     extra_args[c] = NULL;
 
     *krb5_child_extra_args = extra_args;

From c7995fe607b004fb7ef63698d27924b1cc93c05a Mon Sep 17 00:00:00 2001
From: Justin Stephenson <jstep...@redhat.com>
Date: Wed, 10 Nov 2021 17:01:38 +0000
Subject: [PATCH 06/11] gpo: Add chain ID logging support

---
 Makefile.am                     |  3 ++-
 src/providers/ad/ad_gpo.c       | 18 +++++++++++++++++-
 src/providers/ad/ad_gpo_child.c |  8 ++++++++
 3 files changed, 27 insertions(+), 2 deletions(-)

diff --git a/Makefile.am b/Makefile.am
index 490764c49a..e7e7c2920d 100644
--- a/Makefile.am
+++ b/Makefile.am
@@ -4585,7 +4585,8 @@ gpo_child_SOURCES = \
     src/util/atomic_io.c \
     src/util/util.c \
     src/util/util_ext.c \
-    src/util/signal.c
+    src/util/signal.c \
+    src/util/sss_chain_id.c
 gpo_child_CFLAGS = \
     $(AM_CFLAGS) \
     $(POPT_CFLAGS) \
diff --git a/src/providers/ad/ad_gpo.c b/src/providers/ad/ad_gpo.c
index 8f2fe277e1..fa8727d4d4 100644
--- a/src/providers/ad/ad_gpo.c
+++ b/src/providers/ad/ad_gpo.c
@@ -50,6 +50,7 @@
 #include "providers/ldap/sdap.h"
 #include "providers/ldap/sdap_idmap.h"
 #include "util/util_sss_idmap.h"
+#include "util/sss_chain_id.h"
 #include <ndr.h>
 #include <gen_ndr/security.h>
 #include <db/sysdb_computer.h>
@@ -4793,10 +4794,25 @@ gpo_fork_child(struct tevent_req *req)
     int pipefd_from_child[2] = PIPE_INIT;
     pid_t pid;
     errno_t ret;
+    const char **extra_args;
+    int c = 0;
     struct ad_gpo_process_cse_state *state;
 
     state = tevent_req_data(req, struct ad_gpo_process_cse_state);
 
+    extra_args = talloc_array(state, const char *, 2);
+
+    extra_args[c] = talloc_asprintf(extra_args, "--chain-id=%lu",
+                                    sss_chain_id_get());
+    if (extra_args[c] == NULL) {
+        DEBUG(SSSDBG_OP_FAILURE, "talloc_asprintf failed.\n");
+        ret = ENOMEM;
+        goto fail;
+    }
+    c++;
+
+    extra_args[c] = NULL;
+
     ret = pipe(pipefd_from_child);
     if (ret == -1) {
         ret = errno;
@@ -4817,7 +4833,7 @@ gpo_fork_child(struct tevent_req *req)
     if (pid == 0) { /* child */
         exec_child_ex(state,
                       pipefd_to_child, pipefd_from_child,
-                      GPO_CHILD, GPO_CHILD_LOG_FILE, NULL, false,
+                      GPO_CHILD, GPO_CHILD_LOG_FILE, extra_args, false,
                       STDIN_FILENO, AD_GPO_CHILD_OUT_FILENO);
 
         /* We should never get here */
diff --git a/src/providers/ad/ad_gpo_child.c b/src/providers/ad/ad_gpo_child.c
index 8a3a87195b..df11e6eeb7 100644
--- a/src/providers/ad/ad_gpo_child.c
+++ b/src/providers/ad/ad_gpo_child.c
@@ -33,6 +33,7 @@
 
 #include "util/util.h"
 #include "util/child_common.h"
+#include "util/sss_chain_id.h"
 #include "providers/backend.h"
 #include "providers/ad/ad_gpo.h"
 #include "sss_cli.h"
@@ -724,6 +725,7 @@ main(int argc, const char *argv[])
     int opt;
     poptContext pc;
     int debug_fd = -1;
+    uint64_t chain_id;
     const char *opt_logger = NULL;
     errno_t ret;
     int sysvol_gpt_version;
@@ -740,6 +742,8 @@ main(int argc, const char *argv[])
         SSSD_DEBUG_OPTS
         {"debug-fd", 0, POPT_ARG_INT, &debug_fd, 0,
          _("An open file descriptor for the debug logs"), NULL},
+        {"chain-id", 0, POPT_ARG_LONG, &chain_id,
+         0, _("Tevent chain ID used for logging purposes"), NULL},
         SSSD_LOGGER_OPTS
         POPT_TABLEEND
     };
@@ -775,6 +779,10 @@ main(int argc, const char *argv[])
         }
     }
 
+    if (chain_id > 0) {
+        sss_chain_id_set(chain_id);
+    }
+
     DEBUG_INIT(debug_level, opt_logger);
 
     DEBUG(SSSDBG_TRACE_FUNC, "gpo_child started.\n");

From 7f47242f811703e62ec90ec7862ce963401cfb66 Mon Sep 17 00:00:00 2001
From: Justin Stephenson <jstep...@redhat.com>
Date: Wed, 10 Nov 2021 18:20:29 +0000
Subject: [PATCH 07/11] ipa_selinux: Add chain ID logging support

---
 Makefile.am                       |  1 +
 src/providers/ipa/ipa_selinux.c   | 21 +++++++++++++++++++--
 src/providers/ipa/selinux_child.c |  8 ++++++++
 3 files changed, 28 insertions(+), 2 deletions(-)

diff --git a/Makefile.am b/Makefile.am
index e7e7c2920d..7b252df2b7 100644
--- a/Makefile.am
+++ b/Makefile.am
@@ -4561,6 +4561,7 @@ if BUILD_SEMANAGE
 selinux_child_SOURCES = \
     src/providers/ipa/selinux_child.c \
     src/util/sss_semanage.c \
+    src/util/sss_chain_id.c \
     src/util/atomic_io.c \
     src/util/util.c \
     src/util/util_ext.c \
diff --git a/src/providers/ipa/ipa_selinux.c b/src/providers/ipa/ipa_selinux.c
index 7603491342..6f885c0fdb 100644
--- a/src/providers/ipa/ipa_selinux.c
+++ b/src/providers/ipa/ipa_selinux.c
@@ -26,6 +26,7 @@
 #include "db/sysdb_selinux.h"
 #include "util/child_common.h"
 #include "util/sss_selinux.h"
+#include "util/sss_chain_id.h"
 #include "providers/ldap/sdap_async.h"
 #include "providers/ipa/ipa_common.h"
 #include "providers/ipa/ipa_config.h"
@@ -676,6 +677,21 @@ static errno_t selinux_fork_child(struct selinux_child_state *state)
     int pipefd_from_child[2];
     pid_t pid;
     errno_t ret;
+    const char **extra_args;
+    int c = 0;
+
+    extra_args = talloc_array(state, const char *, 2);
+
+    extra_args[c] = talloc_asprintf(extra_args, "--chain-id=%lu",
+                                    sss_chain_id_get());
+    if (extra_args[c] == NULL) {
+        DEBUG(SSSDBG_OP_FAILURE, "talloc_asprintf failed.\n");
+        ret = ENOMEM;
+        return ret;
+    }
+    c++;
+
+    extra_args[c] = NULL;
 
     ret = pipe(pipefd_from_child);
     if (ret == -1) {
@@ -696,8 +712,9 @@ static errno_t selinux_fork_child(struct selinux_child_state *state)
     pid = fork();
 
     if (pid == 0) { /* child */
-        exec_child(state, pipefd_to_child, pipefd_from_child,
-                   SELINUX_CHILD, SELINUX_CHILD_LOG_FILE);
+        exec_child_ex(state, pipefd_to_child, pipefd_from_child,
+                      SELINUX_CHILD, SELINUX_CHILD_LOG_FILE, extra_args,
+                      false, STDIN_FILENO, STDERR_FILENO);
         DEBUG(SSSDBG_CRIT_FAILURE, "Could not exec selinux_child: [%d][%s].\n",
               ret, sss_strerror(ret));
         return ret;
diff --git a/src/providers/ipa/selinux_child.c b/src/providers/ipa/selinux_child.c
index d9b6e15c93..cdd0a3cda2 100644
--- a/src/providers/ipa/selinux_child.c
+++ b/src/providers/ipa/selinux_child.c
@@ -30,6 +30,7 @@
 
 #include "util/util.h"
 #include "util/child_common.h"
+#include "util/sss_chain_id.h"
 #include "providers/backend.h"
 
 struct input_buffer {
@@ -217,12 +218,15 @@ int main(int argc, const char *argv[])
     bool needs_update;
     const char *username;
     const char *opt_logger = NULL;
+    uint64_t chain_id;
 
     struct poptOption long_options[] = {
         POPT_AUTOHELP
         SSSD_DEBUG_OPTS
         {"debug-fd", 0, POPT_ARG_INT, &debug_fd, 0,
          _("An open file descriptor for the debug logs"), NULL},
+        {"chain-id", 0, POPT_ARG_LONG, &chain_id,
+         0, _("Tevent chain ID used for logging purposes"), NULL},
         SSSD_LOGGER_OPTS
         POPT_TABLEEND
     };
@@ -258,6 +262,10 @@ int main(int argc, const char *argv[])
         }
     }
 
+    if (chain_id > 0) {
+        sss_chain_id_set(chain_id);
+    }
+
     DEBUG_INIT(debug_level, opt_logger);
 
     DEBUG(SSSDBG_TRACE_FUNC, "selinux_child started.\n");

From 4c45d5c0e6e45ce814219a8baf5c15fa057c5a1f Mon Sep 17 00:00:00 2001
From: Justin Stephenson <jstep...@redhat.com>
Date: Wed, 10 Nov 2021 18:32:13 +0000
Subject: [PATCH 08/11] p11_child: Add chain ID logging support

---
 Makefile.am                      |  1 +
 src/p11_child/p11_child_common.c | 10 ++++++++++
 src/responder/pam/pamsrv_p11.c   | 10 ++++++++++
 3 files changed, 21 insertions(+)

diff --git a/Makefile.am b/Makefile.am
index 7b252df2b7..76037adaf1 100644
--- a/Makefile.am
+++ b/Makefile.am
@@ -4623,6 +4623,7 @@ p11_child_SOURCES = \
     src/util/atomic_io.c \
     src/util/util.c \
     src/util/util_ext.c \
+    src/util/sss_chain_id.c \
     $(NULL)
 p11_child_SOURCES += src/p11_child/p11_child_openssl.c
 
diff --git a/src/p11_child/p11_child_common.c b/src/p11_child/p11_child_common.c
index 7c8259479d..ce3ed4f7ab 100644
--- a/src/p11_child/p11_child_common.c
+++ b/src/p11_child/p11_child_common.c
@@ -33,6 +33,7 @@
 #include "providers/backend.h"
 #include "util/crypto/sss_crypto.h"
 #include "util/cert.h"
+#include "util/sss_chain_id.h"
 #include "p11_child/p11_child.h"
 
 static const char *op_mode_str(enum op_mode mode)
@@ -161,6 +162,7 @@ int main(int argc, const char *argv[])
     char *key_id = NULL;
     char *label = NULL;
     char *cert_b64 = NULL;
+    uint64_t chain_id;
     bool wait_for_card = false;
     char *uri = NULL;
 
@@ -194,12 +196,16 @@ int main(int argc, const char *argv[])
          _("certificate to verify, base64 encoded"), NULL},
         {"uri", 0, POPT_ARG_STRING, &uri, 0,
          _("PKCS#11 URI to restrict selection"), NULL},
+        {"chain-id", 0, POPT_ARG_LONG, &chain_id,
+         0, _("Tevent chain ID used for logging purposes"), NULL},
         POPT_TABLEEND
     };
 
     /* Set debug level to invalid value so we can decide if -d 0 was used. */
     debug_level = SSSDBG_INVALID;
 
+    debug_from_responder = true;
+
     /*
      * This child can run as root or as sssd user relying on policy kit to
      * grant access to pcscd. This means that no setuid or setgid bit must be
@@ -313,6 +319,10 @@ int main(int argc, const char *argv[])
         }
     }
 
+    if (chain_id > 0) {
+        sss_chain_id_set(chain_id);
+    }
+
     DEBUG_INIT(debug_level, opt_logger);
 
     DEBUG(SSSDBG_TRACE_FUNC, "p11_child started.\n");
diff --git a/src/responder/pam/pamsrv_p11.c b/src/responder/pam/pamsrv_p11.c
index 3b21332db9..3d02bd3feb 100644
--- a/src/responder/pam/pamsrv_p11.c
+++ b/src/responder/pam/pamsrv_p11.c
@@ -29,6 +29,7 @@
 #include "responder/pam/pam_helpers.h"
 #include "lib/certmap/sss_certmap.h"
 #include "util/crypto/sss_crypto.h"
+#include "util/sss_chain_id.h"
 #include "db/sysdb.h"
 
 
@@ -722,6 +723,7 @@ struct tevent_req *pam_check_cert_send(TALLOC_CTX *mem_ctx,
     uint8_t *write_buf = NULL;
     size_t write_buf_len = 0;
     size_t arg_c;
+    uint64_t chain_id;
     const char *module_name = NULL;
     const char *token_name = NULL;
     const char *key_id = NULL;
@@ -746,6 +748,14 @@ struct tevent_req *pam_check_cert_send(TALLOC_CTX *mem_ctx,
 
     /* extra_args are added in revers order */
     arg_c = 0;
+
+    chain_id = sss_chain_id_get();
+
+    if (chain_id > 0) {
+        extra_args[arg_c++] = talloc_asprintf(mem_ctx, "%lu", chain_id);
+        extra_args[arg_c++] = "--chain-id";
+    }
+
     if (uri != NULL) {
         DEBUG(SSSDBG_TRACE_ALL, "Adding PKCS#11 URI [%s].\n", uri);
         extra_args[arg_c++] = uri;

From 08804474d2d7a69850cd0b2393a682f3bb459bb3 Mon Sep 17 00:00:00 2001
From: Justin Stephenson <jstep...@redhat.com>
Date: Thu, 28 Oct 2021 17:41:47 +0000
Subject: [PATCH 09/11] proxy_child: Add chain ID logging support

---
 src/providers/proxy/proxy_auth.c  | 6 ++++--
 src/providers/proxy/proxy_child.c | 8 ++++++++
 2 files changed, 12 insertions(+), 2 deletions(-)

diff --git a/src/providers/proxy/proxy_auth.c b/src/providers/proxy/proxy_auth.c
index 0e6fc8ea84..9af1b1f669 100644
--- a/src/providers/proxy/proxy_auth.c
+++ b/src/providers/proxy/proxy_auth.c
@@ -26,6 +26,7 @@
 
 #include "providers/proxy/proxy.h"
 #include "sss_iface/sss_iface_async.h"
+#include "util/sss_chain_id.h"
 
 struct pc_init_ctx;
 
@@ -178,11 +179,12 @@ static struct tevent_req *proxy_child_init_send(TALLOC_CTX *mem_ctx,
 
     state->command = talloc_asprintf(req,
             "%s/proxy_child -d %#.4x --debug-timestamps=%d "
-            "--debug-microseconds=%d --logger=%s --domain %s --id %d",
+            "--debug-microseconds=%d --logger=%s --domain %s --id %d "
+            "--chain-id=%lu",
             SSSD_LIBEXEC_PATH, debug_level, debug_timestamps,
             debug_microseconds, sss_logger_str[sss_logger],
             auth_ctx->be->domain->name,
-            child_ctx->id);
+            child_ctx->id, sss_chain_id_get());
     if (state->command == NULL) {
         DEBUG(SSSDBG_CRIT_FAILURE, "talloc_asprintf failed.\n");
         return NULL;
diff --git a/src/providers/proxy/proxy_child.c b/src/providers/proxy/proxy_child.c
index d9e3d0d874..790261f00e 100644
--- a/src/providers/proxy/proxy_child.c
+++ b/src/providers/proxy/proxy_child.c
@@ -43,6 +43,7 @@
 #include "confdb/confdb.h"
 #include "providers/proxy/proxy.h"
 #include "sss_iface/sss_iface_async.h"
+#include "util/sss_chain_id.h"
 
 #include "providers/backend.h"
 
@@ -480,6 +481,7 @@ int main(int argc, const char *argv[])
     struct main_context *main_ctx;
     int ret;
     long id = 0;
+    long chain_id;
     char *pam_target = NULL;
     uid_t uid;
     gid_t gid;
@@ -493,6 +495,8 @@ int main(int argc, const char *argv[])
          _("Domain of the information provider (mandatory)"), NULL },
         {"id", 0, POPT_ARG_LONG, &id, 0,
          _("Child identifier (mandatory)"), NULL },
+        {"chain-id", 0, POPT_ARG_LONG, &chain_id, 0,
+         _("Tevent chain ID used for logging purposes"), NULL },
         POPT_TABLEEND
     };
 
@@ -556,6 +560,10 @@ int main(int argc, const char *argv[])
     conf_entry = talloc_asprintf(NULL, CONFDB_DOMAIN_PATH_TMPL, domain);
     if (!conf_entry) return 2;
 
+    if (chain_id > 0) {
+        sss_chain_id_set(chain_id);
+    }
+
     ret = server_setup(srv_name, 0, 0, 0, conf_entry, &main_ctx);
     if (ret != EOK) {
         DEBUG(SSSDBG_FATAL_FAILURE, "Could not set up mainloop [%d]\n", ret);

From 7169814106df4ed460fadf9a2c364e0a02631488 Mon Sep 17 00:00:00 2001
From: Justin Stephenson <jstep...@redhat.com>
Date: Fri, 29 Oct 2021 14:37:49 +0000
Subject: [PATCH 10/11] Analyzer: Parse the responder request ID

This is needed to parse out the responder request ID field properly. Due
to Responder tevent chain ID support, the Request ID is in a
different part of the log message.
---
 src/tools/analyzer/modules/request.py | 15 +++++++--------
 1 file changed, 7 insertions(+), 8 deletions(-)

diff --git a/src/tools/analyzer/modules/request.py b/src/tools/analyzer/modules/request.py
index 098a9197bb..4c513186df 100644
--- a/src/tools/analyzer/modules/request.py
+++ b/src/tools/analyzer/modules/request.py
@@ -147,8 +147,8 @@ def print_formatted(self, line, verbose):
         if line.startswith('   *  '):
             return
         fields = line.split("[")
-        cr_field = fields[2].split(":")[1]
-        cr = cr_field[5:]
+        cr_field = fields[3][7:]
+        cr = cr_field.split(":")[0][4:]
         if "refreshed" in line:
             return
         # CR Plugin name
@@ -165,7 +165,7 @@ def print_formatted(self, line, verbose):
             ts = line.split(")")[0]
             ts = ts[1:]
             fields = line.split("[")
-            cid = fields[3][5:-1]
+            cid = fields[3][4:-9]
             cmd = fields[4][4:-1]
             uid = fields[5][4:-1]
             if not uid.isnumeric():
@@ -198,10 +198,11 @@ def list_requests(self, source, verbose, pam):
         """
         component = source.Component.NSS
         resp = "nss"
+        # Log messages matching the following regex patterns contain
+        # the useful info we need to produce list output
         patterns = ['\[cmd']
         patterns.append("(cache_req_send|cache_req_process_input|"
                         "cache_req_search_send)")
-        consume = True
         if pam:
             component = source.Component.PAM
             resp = "pam"
@@ -209,7 +210,6 @@ def list_requests(self, source, verbose, pam):
         logger.info(f"******** Listing {resp} client requests ********")
         source.set_component(component)
         self.done = ""
-        # For each CID
         for line in self.matched_line(source, patterns):
             if isinstance(source, Journald):
                 print(line)
@@ -238,7 +238,8 @@ def track_request(self, source, cid, merge, cachereq, pam):
         if pam:
             component = source.Component.PAM
             resp = "pam"
-            pam_data_regex = f'pam_print_data.*\[CID #{cid}\]'
+            pam_data_regex = f'pam.*\[CID#{cid}\]'
+            pattern.append(pam_data_regex)
 
         logger.info(f"******** Checking {resp} responder for Client ID"
                     f" {cid} *******")
@@ -261,8 +262,6 @@ def track_request(self, source, cid, merge, cachereq, pam):
         pattern.clear()
         [pattern.append(f'\\{id}') for id in be_ids]
 
-        if pam:
-            pattern.append(pam_data_regex)
         for match in self.matched_line(source, pattern):
             be_results = self.consume_line(match, source, merge)
 

From b668515c2eea018f78e97fb7694a9e7da0a39ecb Mon Sep 17 00:00:00 2001
From: Justin Stephenson <jstep...@redhat.com>
Date: Thu, 4 Nov 2021 00:05:20 +0000
Subject: [PATCH 11/11] Analyzer: Add --child argument to 'request show'

The analyzer tool will search for requests (RID# log messages)
in any existing child log files when --child is provided.
---
 src/tools/analyzer/modules/request.py | 16 ++++++++++------
 src/tools/analyzer/source_files.py    | 14 +++++++++-----
 2 files changed, 19 insertions(+), 11 deletions(-)

diff --git a/src/tools/analyzer/modules/request.py b/src/tools/analyzer/modules/request.py
index 4c513186df..3b2b7e688a 100644
--- a/src/tools/analyzer/modules/request.py
+++ b/src/tools/analyzer/modules/request.py
@@ -32,11 +32,13 @@ def list(ctx, verbose, pam):
 @click.option("--cachereq", is_flag=True, help="Include cache request "
               "related logs")
 @click.option("--pam", is_flag=True, help="Track only PAM requests")
+@click.option("--child", is_flag=True, help="Include searching in child "
+              "log files")
 @click.pass_obj
-def show(ctx, cid, merge, cachereq, pam):
+def show(ctx, cid, merge, cachereq, pam, child):
     analyzer = RequestAnalyzer()
     source = analyzer.load(ctx)
-    analyzer.track_request(source, cid, merge, cachereq, pam)
+    analyzer.track_request(source, cid, merge, cachereq, pam, child)
 
 
 class RequestAnalyzer:
@@ -208,7 +210,7 @@ def list_requests(self, source, verbose, pam):
             resp = "pam"
 
         logger.info(f"******** Listing {resp} client requests ********")
-        source.set_component(component)
+        source.set_component(component, False)
         self.done = ""
         for line in self.matched_line(source, patterns):
             if isinstance(source, Journald):
@@ -216,7 +218,7 @@ def list_requests(self, source, verbose, pam):
             else:
                 self.print_formatted(line, verbose)
 
-    def track_request(self, source, cid, merge, cachereq, pam):
+    def track_request(self, source, cid, merge, cachereq, pam, child):
         """
         Print Logs pertaining to individual SSSD client request
 
@@ -227,6 +229,8 @@ def track_request(self, source, cid, merge, cachereq, pam):
                 by timestamp
             pam (bool): True if --pam cli option is provided, track requests
                 in the PAM responder
+            child (bool): True if --child cli option is provided, include
+                child log files in search
         """
         resp_results = False
         be_results = False
@@ -243,7 +247,7 @@ def track_request(self, source, cid, merge, cachereq, pam):
 
         logger.info(f"******** Checking {resp} responder for Client ID"
                     f" {cid} *******")
-        source.set_component(component)
+        source.set_component(component, child)
         if cachereq:
             cr_id_regex = 'CR #[0-9]+'
             cr_ids = self.get_linked_ids(source, pattern, cr_id_regex)
@@ -254,7 +258,7 @@ def track_request(self, source, cid, merge, cachereq, pam):
 
         logger.info(f"********* Checking Backend for Client ID {cid} ********")
         pattern = [f'REQ_TRACE.*\[sssd.{resp} CID #{cid}\]']
-        source.set_component(source.Component.BE)
+        source.set_component(source.Component.BE, child)
 
         be_id_regex = '\[RID#[0-9]+\]'
         be_ids = self.get_linked_ids(source, pattern, be_id_regex)
diff --git a/src/tools/analyzer/source_files.py b/src/tools/analyzer/source_files.py
index df87f92fbd..90496a72eb 100644
--- a/src/tools/analyzer/source_files.py
+++ b/src/tools/analyzer/source_files.py
@@ -46,19 +46,22 @@ def resolve_path(self, path):
         else:
             return path + "/"
 
-    def get_domain_logfiles(self):
+    def get_domain_logfiles(self, child=False):
         """ Retrieve list of SSSD log files, exclude rotated (.gz) files """
         domain_files = []
         exclude_list = ["ifp", "nss", "pam", "sudo", "autofs",
                         "ssh", "pac", "kcm", ".gz"]
-        file_list = glob.glob(self.path + "sssd_*")
+        if child:
+            file_list = glob.glob(self.path + "*.log")
+        else:
+            file_list = glob.glob(self.path + "sssd_*")
         for file in file_list:
             if not any(s in file for s in exclude_list):
                 domain_files.append(file)
 
         return domain_files
 
-    def set_component(self, component):
+    def set_component(self, component, child):
         """
         Switch the reader to interact with a certain SSSD component
         NSS, PAM, BE
@@ -69,8 +72,9 @@ def set_component(self, component):
         elif component == self.Component.PAM:
             self.log_files.append(self.path + "sssd_pam.log")
         elif component == self.Component.BE:
-            if not self.domains:
+            domains = self.get_domain_logfiles(child)
+            if not domains:
                 raise IOError
             # error: No domains found?
-            for dom in self.domains:
+            for dom in domains:
                 self.log_files.append(dom)
_______________________________________________
sssd-devel mailing list -- sssd-devel@lists.fedorahosted.org
To unsubscribe send an email to sssd-devel-le...@lists.fedorahosted.org
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/sssd-devel@lists.fedorahosted.org
Do not reply to spam on the list, report it: 
https://pagure.io/fedora-infrastructure

Reply via email to