From 1b963665272272e59718ebee7b7b3e432929cfc8 Mon Sep 17 00:00:00 2001
From: Ludwig Krispenz <lkrispen@redhat.com>
Date: Thu, 9 Aug 2018 13:07:46 +0200
Subject: [PATCH] ticket 49029 - modification of logging format for internal
 ops triggered by external ones

---
 ldap/servers/slapd/add.c      |  4 +++-
 ldap/servers/slapd/delete.c   |  4 +++-
 ldap/servers/slapd/modify.c   |  4 +++-
 ldap/servers/slapd/modrdn.c   |  3 ++-
 ldap/servers/slapd/opshared.c | 25 ++++++++++++++++++-------
 ldap/servers/slapd/result.c   | 33 ++++++++++++++++++++-------------
 6 files changed, 49 insertions(+), 24 deletions(-)

diff --git a/ldap/servers/slapd/add.c b/ldap/servers/slapd/add.c
index f3ae8b65d..ae3262b7d 100644
--- a/ldap/servers/slapd/add.c
+++ b/ldap/servers/slapd/add.c
@@ -468,7 +468,9 @@ op_shared_add(Slapi_PBlock *pb)
             int32_t op_id;
             int32_t op_internal_id;
             get_internal_conn_op(&connid, &op_id, &op_internal_id);
-            slapi_log_access(LDAP_DEBUG_ARGS, "conn=Internal(%" PRId64 ") op=%d(%d) ADD dn=\"%s\"\n",
+            slapi_log_access(LDAP_DEBUG_ARGS,
+                    connid==0 ? "conn=Internal(%" PRId64 ") op=%d(%d) ADD dn=\"%s\"\n" :
+                                    "conn=%" PRId64 " (Internal) op=%d(%d) ADD dn=\"%s\"\n",
                              connid,
                              op_id,
                              op_internal_id,
diff --git a/ldap/servers/slapd/delete.c b/ldap/servers/slapd/delete.c
index 39d5baf32..e16ab3390 100644
--- a/ldap/servers/slapd/delete.c
+++ b/ldap/servers/slapd/delete.c
@@ -273,7 +273,9 @@ op_shared_delete(Slapi_PBlock *pb)
             int32_t op_id;
             int32_t op_internal_id;
             get_internal_conn_op(&connid, &op_id, &op_internal_id);
-            slapi_log_access(LDAP_DEBUG_ARGS, "conn=Internal(%" PRIu64 ") op=%d(%d) DEL dn=\"%s\"%s\n",
+            slapi_log_access(LDAP_DEBUG_ARGS,
+                             connid==0 ? "conn=Internal(%" PRId64 ") op=%d(%d) DEL dn=\"%s\"\n" :
+                                    "conn=%" PRId64 " (Internal) op=%d(%d) DEL dn=\"%s\"\n",
                              connid,
                              op_id,
                              op_internal_id,
diff --git a/ldap/servers/slapd/modify.c b/ldap/servers/slapd/modify.c
index 476cde712..c60ee13e7 100644
--- a/ldap/servers/slapd/modify.c
+++ b/ldap/servers/slapd/modify.c
@@ -677,7 +677,9 @@ op_shared_modify(Slapi_PBlock *pb, int pw_change, char *old_pw)
             int32_t op_id;
             int32_t op_internal_id;
             get_internal_conn_op(&connid, &op_id, &op_internal_id);
-            slapi_log_access(LDAP_DEBUG_ARGS, "conn=Internal(%" PRIu64 ") op=%d(%d) MOD dn=\"%s\"%s\n",
+            slapi_log_access(LDAP_DEBUG_ARGS,
+                             connid==0 ? "conn=Internal(%" PRId64 ") op=%d(%d) MOD dn=\"%s\"\n" :
+                                    "conn=%" PRId64 " (Internal) op=%d(%d) MOD dn=\"%s\"\n",
                              connid,
                              op_id,
                              op_internal_id,
diff --git a/ldap/servers/slapd/modrdn.c b/ldap/servers/slapd/modrdn.c
index df4dab9c1..bfac9ff7f 100644
--- a/ldap/servers/slapd/modrdn.c
+++ b/ldap/servers/slapd/modrdn.c
@@ -481,7 +481,8 @@ op_shared_rename(Slapi_PBlock *pb, int passin_args)
             int32_t op_internal_id;
             get_internal_conn_op(&connid, &op_id, &op_internal_id);
             slapi_log_access(LDAP_DEBUG_ARGS,
-                             "conn=Internal(%" PRIu64 ") op=%d(%d) MODRDN dn=\"%s\" newrdn=\"%s\" newsuperior=\"%s\"%s\n",
+                             connid==0 ? "conn=Internal(%" PRId64 ") op=%d(%d) MODRDN dn=\"%s\" newrdn=\"%s\" newsuperior=\"%s\"%s\n" :
+                                    "conn=%" PRId64 " (Internal) op=%d(%d) MODRDN dn=\"%s\" newrdn=\"%s\" newsuperior=\"%s\"%s\n",
                              connid,
                              op_id,
                              op_internal_id,
diff --git a/ldap/servers/slapd/opshared.c b/ldap/servers/slapd/opshared.c
index e4433ba2e..9ec758d1b 100644
--- a/ldap/servers/slapd/opshared.c
+++ b/ldap/servers/slapd/opshared.c
@@ -292,12 +292,19 @@ op_shared_search(Slapi_PBlock *pb, int send_result)
 
     if (operation_is_flag_set(operation, OP_FLAG_ACTION_LOG_ACCESS)) {
         char *fmtstr;
+        uint64_t connid;
+        int32_t op_id;
+        int32_t op_internal_id;
 
 #define SLAPD_SEARCH_FMTSTR_BASE "conn=%" PRIu64 " op=%d SRCH base=\"%s\" scope=%d "
-#define SLAPD_SEARCH_FMTSTR_BASE_INT "conn=Internal(%" PRIu64 ") op=%d(%d) SRCH base=\"%s\" scope=%d "
+#define SLAPD_SEARCH_FMTSTR_BASE_INT_INT "conn=Internal(%" PRIu64 ") op=%d(%d) SRCH base=\"%s\" scope=%d "
+#define SLAPD_SEARCH_FMTSTR_BASE_EXT_INT "conn=%" PRIu64 " (Internal) op=%d(%d) SRCH base=\"%s\" scope=%d "
 #define SLAPD_SEARCH_FMTSTR_REMAINDER " attrs=%s%s%s\n"
 
         PR_ASSERT(fstr);
+        if (internal_op) {
+            get_internal_conn_op(&connid, &op_id, &op_internal_id);
+        }
         if (strlen(fstr) > 1024) {
             /*
            * slapi_log_access() throws away log lines that are longer than
@@ -307,13 +314,21 @@ op_shared_search(Slapi_PBlock *pb, int send_result)
             if (!internal_op) {
                 fmtstr = SLAPD_SEARCH_FMTSTR_BASE "filter=\"%.1024s...\"" SLAPD_SEARCH_FMTSTR_REMAINDER;
             } else {
-                fmtstr = SLAPD_SEARCH_FMTSTR_BASE_INT "filter=\"%.1024s...\"" SLAPD_SEARCH_FMTSTR_REMAINDER;
+                if (connid == 0) {
+                    fmtstr = SLAPD_SEARCH_FMTSTR_BASE_INT_INT "filter=\"%.1024s...\"" SLAPD_SEARCH_FMTSTR_REMAINDER;
+                } else {
+                    fmtstr = SLAPD_SEARCH_FMTSTR_BASE_EXT_INT "filter=\"%.1024s...\"" SLAPD_SEARCH_FMTSTR_REMAINDER;
+                }
             }
         } else {
             if (!internal_op) {
                 fmtstr = SLAPD_SEARCH_FMTSTR_BASE "filter=\"%s\"" SLAPD_SEARCH_FMTSTR_REMAINDER;
             } else {
-                fmtstr = SLAPD_SEARCH_FMTSTR_BASE_INT "filter=\"%s\"" SLAPD_SEARCH_FMTSTR_REMAINDER;
+                if (connid == 0) {
+                    fmtstr = SLAPD_SEARCH_FMTSTR_BASE_INT_INT "filter=\"%s\"" SLAPD_SEARCH_FMTSTR_REMAINDER;
+                } else {
+                    fmtstr = SLAPD_SEARCH_FMTSTR_BASE_EXT_INT "filter=\"%s\"" SLAPD_SEARCH_FMTSTR_REMAINDER;
+                }
             }
         }
 
@@ -338,10 +353,6 @@ op_shared_search(Slapi_PBlock *pb, int send_result)
                              flag_psearch ? " options=persistent" : "",
                              proxystr ? proxystr : "");
         } else {
-            uint64_t connid;
-            int32_t op_id;
-            int32_t op_internal_id;
-            get_internal_conn_op(&connid, &op_id, &op_internal_id);
             slapi_log_access(LDAP_DEBUG_ARGS, fmtstr,
                              connid,
                              op_id,
diff --git a/ldap/servers/slapd/result.c b/ldap/servers/slapd/result.c
index 04eb2e675..ee7a3f298 100644
--- a/ldap/servers/slapd/result.c
+++ b/ldap/servers/slapd/result.c
@@ -1946,6 +1946,8 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries
         }
     }
 
+#define LOG_CONN_OP_FMT_INT_INT "conn=Internal(%" PRIu64 ") op=%d(%d) RESULT err=%d"
+#define LOG_CONN_OP_FMT_EXT_INT "conn=%" PRIu64 " (Internal) op=%d(%d) RESULT err=%d"
     if (op->o_tag == LDAP_REQ_BIND && err == LDAP_SASL_BIND_IN_PROGRESS) {
         /*
          * Not actually an error.
@@ -1963,10 +1965,10 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries
                              notes_str, csn_str);
         } else {
 
+#define LOG_SASLMSG_FMT " tag=%" BERTAG_T " nentries=%d etime=%s%s%s, SASL bind in progress\n"
             slapi_log_access(LDAP_DEBUG_ARGS,
-                             "conn=Internal(%" PRIu64 ") op=%d(%d) RESULT err=%d"
-                             " tag=%" BERTAG_T " nentries=%d etime=%s%s%s"
-                             ", SASL bind in progress\n",
+                             connid == 0 ? LOG_CONN_OP_FMT_INT_INT LOG_SASLMSG_FMT :
+                                           LOG_CONN_OP_FMT_EXT_INT LOG_SASLMSG_FMT,
                              connid,
                              op_id,
                              op_internal_id,
@@ -1993,10 +1995,10 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries
                              etime,
                              notes_str, csn_str, dn ? dn : "");
         } else {
+#define LOG_BINDMSG_FMT " tag=%" BERTAG_T " nentries=%d etime=%s%s%s dn=\"%s\"\n"
             slapi_log_access(LDAP_DEBUG_ARGS,
-                             "conn=Internal(%" PRIu64 ") op=%d(%d) RESULT err=%d"
-                             " tag=%" BERTAG_T " nentries=%d etime=%s%s%s"
-                             " dn=\"%s\"\n",
+                             connid == 0 ? LOG_CONN_OP_FMT_INT_INT LOG_BINDMSG_FMT :
+                                           LOG_CONN_OP_FMT_EXT_INT LOG_BINDMSG_FMT,
                              connid,
                              op_id,
                              op_internal_id,
@@ -2018,10 +2020,10 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries
                                  etime,
                                  notes_str, csn_str, pr_idx, pr_cookie);
             } else {
+#define LOG_PRMSG_FMT " tag=%" BERTAG_T " nentries=%d etime=%s%s%s pr_idx=%d pr_cookie=%d \n"
                 slapi_log_access(LDAP_DEBUG_ARGS,
-                                 "conn=Internal(%" PRIu64 ") op=%d(%d) RESULT err=%d"
-                                 " tag=%" BERTAG_T " nentries=%d etime=%s%s%s"
-                                 " pr_idx=%d pr_cookie=%d \n",
+                                 connid == 0 ? LOG_CONN_OP_FMT_INT_INT LOG_PRMSG_FMT :
+                                               LOG_CONN_OP_FMT_EXT_INT LOG_PRMSG_FMT,
                                  connid,
                                  op_id,
                                  op_internal_id,
@@ -2052,9 +2054,10 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries
             }
         } else {
             int optype;
+#define LOG_MSG_FMT " tag=%" BERTAG_T " nentries=%d etime=%s%s%s\n"
             slapi_log_access(LDAP_DEBUG_ARGS,
-                             "conn=Internal(%" PRIu64 ") op=%d(%d) RESULT err=%d"
-                             " tag=%" BERTAG_T " nentries=%d etime=%s%s%s\n",
+                             connid == 0 ? LOG_CONN_OP_FMT_INT_INT LOG_MSG_FMT :
+                                           LOG_CONN_OP_FMT_EXT_INT LOG_MSG_FMT,
                              connid,
                              op_id,
                              op_internal_id,
@@ -2115,7 +2118,9 @@ log_entry(Operation *op, Slapi_Entry *e)
             int32_t op_id;
             int32_t op_internal_id;
             get_internal_conn_op(&connid, &op_id, &op_internal_id);
-            slapi_log_access(LDAP_DEBUG_ARGS, "conn=Internal(%" PRIu64 ") op=%d(%d) ENTRY dn=\"%s\"\n",
+            slapi_log_access(LDAP_DEBUG_ARGS,
+                             connid == 0 ? "conn=Internal(%" PRIu64 ") op=%d(%d) ENTRY dn=\"%s\"\n" :
+                                           "conn=%" PRIu64 " (Internal) op=%d(%d) ENTRY dn=\"%s\"\n",
                              connid,
                              op_id,
                              op_internal_id,
@@ -2141,7 +2146,9 @@ log_referral(Operation *op)
             int32_t op_id;
             int32_t op_internal_id;
             get_internal_conn_op(&connid, &op_id, &op_internal_id);
-            slapi_log_access(LDAP_DEBUG_ARGS, "conn=Internal(%" PRIu64 ") op=%d(%d) REFERRAL\n",
+            slapi_log_access(LDAP_DEBUG_ARGS,
+                             connid == 0 ? "conn=Internal(%" PRIu64 ") op=%d(%d) REFERRAL\n" :
+                                           "conn=%" PRIu64 " (Internal) op=%d(%d) ENTRY\n",
                              connid, op_id, op_internal_id);
         }
     }
-- 
2.17.1

