From 1b963665272272e59718ebee7b7b3e432929cfc8 Mon Sep 17 00:00:00 2001 From: Ludwig Krispenz 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