From a7dfa383d103944dfd27fff98152138c1b0fd0f7 Mon Sep 17 00:00:00 2001 From: Mark Reynolds Date: Oct 31 2018 13:55:15 +0000 Subject: Ticket 49995 - Fix issues with internal op logging Bug Description: ----------------- At server startup the server's internal operatons performed by bootstrapping occurred before the thread data was initialized. This caused random values in the logging counters [1]. It was also observed that nested operations(and nested-nested operations, etc) were not properly logged [2]. Fix Description: ----------------- [1] Move the thread initialization higher up in main() [2] Changed the way we log nested internal operations. Instead, we keep the internal op number the same for nested ops but also now display the nested level. https://pagure.io/389-ds-base/issue/49995 Reviewed by: lkrispenz, amsharma, firstyear (Thanks!) --- diff --git a/ldap/servers/slapd/add.c b/ldap/servers/slapd/add.c index 65e9b56..942f225 100644 --- a/ldap/servers/slapd/add.c +++ b/ldap/servers/slapd/add.c @@ -467,13 +467,15 @@ op_shared_add(Slapi_PBlock *pb) uint64_t connid; int32_t op_id; int32_t op_internal_id; - get_internal_conn_op(&connid, &op_id, &op_internal_id); + int32_t op_nested_count; + get_internal_conn_op(&connid, &op_id, &op_internal_id, &op_nested_count); 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==0 ? "conn=Internal(%" PRId64 ") op=%d(%d)(%d) ADD dn=\"%s\"\n" : + "conn=%" PRId64 " (Internal) op=%d(%d)(%d) ADD dn=\"%s\"\n", connid, op_id, op_internal_id, + op_nested_count, slapi_entry_get_dn_const(e)); } } diff --git a/ldap/servers/slapd/delete.c b/ldap/servers/slapd/delete.c index e740eb2..c0e61ad 100644 --- a/ldap/servers/slapd/delete.c +++ b/ldap/servers/slapd/delete.c @@ -272,13 +272,15 @@ op_shared_delete(Slapi_PBlock *pb) uint64_t connid; int32_t op_id; int32_t op_internal_id; - get_internal_conn_op(&connid, &op_id, &op_internal_id); + int32_t op_nested_count; + get_internal_conn_op(&connid, &op_id, &op_internal_id, &op_nested_count); slapi_log_access(LDAP_DEBUG_ARGS, - connid==0 ? "conn=Internal(%" PRId64 ") op=%d(%d) DEL dn=\"%s\"%s\n" : - "conn=%" PRId64 " (Internal) op=%d(%d) DEL dn=\"%s\"%s\n", + connid==0 ? "conn=Internal(%" PRId64 ") op=%d(%d)(%d) DEL dn=\"%s\"%s\n" : + "conn=%" PRId64 " (Internal) op=%d(%d)(%d) DEL dn=\"%s\"%s\n", connid, op_id, op_internal_id, + op_nested_count, slapi_sdn_get_dn(sdn), proxystr ? proxystr : ""); } diff --git a/ldap/servers/slapd/main.c b/ldap/servers/slapd/main.c index d175dcd..8423641 100644 --- a/ldap/servers/slapd/main.c +++ b/ldap/servers/slapd/main.c @@ -754,6 +754,15 @@ main(int argc, char **argv) g_log_init(); vattr_init(); + /* + * init the thread data indexes. Nothing should be creating their + * own thread data, and should be using this function instead + * as we may swap to context based storage in the future rather + * than direct thread-local accesses (especially important with + * consideration of rust etc) + */ + slapi_td_init(); + if (mcfg.slapd_exemode == SLAPD_EXEMODE_REFERRAL) { slapdFrontendConfig = getFrontendConfig(); /* make up the config stuff */ @@ -942,17 +951,6 @@ main(int argc, char **argv) } /* - * init the thread data indexes. Nothing should be creating their - * own thread data, and should be using this function instead - * as we may swap to context based storage in the future rather - * than direct thread-local accesses (especially important with - * consideration of rust etc) - * - * DOES THIS NEED TO BE BEFORE OR AFTER NS? - */ - slapi_td_init(); - - /* * Create our thread pool here for tasks to utilise. */ main_create_ns(&tp); diff --git a/ldap/servers/slapd/modify.c b/ldap/servers/slapd/modify.c index 01cf722..de46746 100644 --- a/ldap/servers/slapd/modify.c +++ b/ldap/servers/slapd/modify.c @@ -676,13 +676,15 @@ op_shared_modify(Slapi_PBlock *pb, int pw_change, char *old_pw) uint64_t connid; int32_t op_id; int32_t op_internal_id; - get_internal_conn_op(&connid, &op_id, &op_internal_id); + int32_t op_nested_count; + get_internal_conn_op(&connid, &op_id, &op_internal_id, &op_nested_count); slapi_log_access(LDAP_DEBUG_ARGS, - connid==0 ? "conn=Internal(%" PRId64 ") op=%d(%d) MOD dn=\"%s\"%s\n" : - "conn=%" PRId64 " (Internal) op=%d(%d) MOD dn=\"%s\"%s\n", + connid==0 ? "conn=Internal(%" PRId64 ") op=%d(%d)(%d) MOD dn=\"%s\"%s\n" : + "conn=%" PRId64 " (Internal) op=%d(%d)(%d) MOD dn=\"%s\"%s\n", connid, op_id, op_internal_id, + op_nested_count, slapi_sdn_get_dn(sdn), proxystr ? proxystr : ""); } diff --git a/ldap/servers/slapd/modrdn.c b/ldap/servers/slapd/modrdn.c index e22997e..3efe584 100644 --- a/ldap/servers/slapd/modrdn.c +++ b/ldap/servers/slapd/modrdn.c @@ -479,13 +479,15 @@ op_shared_rename(Slapi_PBlock *pb, int passin_args) uint64_t connid; int32_t op_id; int32_t op_internal_id; - get_internal_conn_op(&connid, &op_id, &op_internal_id); + int32_t op_nested_count; + get_internal_conn_op(&connid, &op_id, &op_internal_id, &op_nested_count); slapi_log_access(LDAP_DEBUG_ARGS, - 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==0 ? "conn=Internal(%" PRId64 ") op=%d(%d)(%d) MODRDN dn=\"%s\" newrdn=\"%s\" newsuperior=\"%s\"%s\n" : + "conn=%" PRId64 " (Internal) op=%d(%d)(%d) MODRDN dn=\"%s\" newrdn=\"%s\" newsuperior=\"%s\"%s\n", connid, op_id, op_internal_id, + op_nested_count, dn, newrdn ? newrdn : "(null)", newsuperior ? newsuperior : "(null)", diff --git a/ldap/servers/slapd/opshared.c b/ldap/servers/slapd/opshared.c index 9ec758d..18bf3a5 100644 --- a/ldap/servers/slapd/opshared.c +++ b/ldap/servers/slapd/opshared.c @@ -295,15 +295,16 @@ op_shared_search(Slapi_PBlock *pb, int send_result) uint64_t connid; int32_t op_id; int32_t op_internal_id; + int32_t op_nested_count; #define SLAPD_SEARCH_FMTSTR_BASE "conn=%" PRIu64 " op=%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_BASE_INT_INT "conn=Internal(%" PRIu64 ") op=%d(%d)(%d) SRCH base=\"%s\" scope=%d " +#define SLAPD_SEARCH_FMTSTR_BASE_EXT_INT "conn=%" PRIu64 " (Internal) op=%d(%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); + get_internal_conn_op(&connid, &op_id, &op_internal_id, &op_nested_count); } if (strlen(fstr) > 1024) { /* @@ -357,6 +358,7 @@ op_shared_search(Slapi_PBlock *pb, int send_result) connid, op_id, op_internal_id, + op_nested_count, normbase, scope, fstr, attrliststr, flag_psearch ? " options=persistent" : "", diff --git a/ldap/servers/slapd/result.c b/ldap/servers/slapd/result.c index 0570f31..a03ca43 100644 --- a/ldap/servers/slapd/result.c +++ b/ldap/servers/slapd/result.c @@ -1914,8 +1914,9 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries uint64_t connid; int32_t op_id; int32_t op_internal_id; + int32_t op_nested_count; - get_internal_conn_op(&connid, &op_id, &op_internal_id); + get_internal_conn_op(&connid, &op_id, &op_internal_id, &op_nested_count); slapi_pblock_get(pb, SLAPI_PAGED_RESULTS_INDEX, &pr_idx); slapi_pblock_get(pb, SLAPI_PAGED_RESULTS_COOKIE, &pr_cookie); @@ -1946,8 +1947,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" +#define LOG_CONN_OP_FMT_INT_INT "conn=Internal(%" PRIu64 ") op=%d(%d)(%d) RESULT err=%d" +#define LOG_CONN_OP_FMT_EXT_INT "conn=%" PRIu64 " (Internal) op=%d(%d)(%d) RESULT err=%d" if (op->o_tag == LDAP_REQ_BIND && err == LDAP_SASL_BIND_IN_PROGRESS) { /* * Not actually an error. @@ -1972,6 +1973,7 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries connid, op_id, op_internal_id, + op_nested_count, err, tag, nentries, etime, notes_str, csn_str); @@ -2002,6 +2004,7 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries connid, op_id, op_internal_id, + op_nested_count, err, tag, nentries, etime, notes_str, csn_str, dn ? dn : ""); @@ -2027,6 +2030,7 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries connid, op_id, op_internal_id, + op_nested_count, err, tag, nentries, etime, notes_str, csn_str, pr_idx, pr_cookie); @@ -2061,6 +2065,7 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries connid, op_id, op_internal_id, + op_nested_count, err, tag, nentries, etime, notes_str, csn_str); @@ -2117,13 +2122,15 @@ log_entry(Operation *op, Slapi_Entry *e) uint64_t connid; int32_t op_id; int32_t op_internal_id; - get_internal_conn_op(&connid, &op_id, &op_internal_id); + int32_t op_nested_count; + get_internal_conn_op(&connid, &op_id, &op_internal_id, &op_nested_count); 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 == 0 ? "conn=Internal(%" PRIu64 ") op=%d(%d)(%d) ENTRY dn=\"%s\"\n" : + "conn=%" PRIu64 " (Internal) op=%d(%d)(%d) ENTRY dn=\"%s\"\n", connid, op_id, op_internal_id, + op_nested_count, slapi_entry_get_dn_const(e)); } } @@ -2145,11 +2152,12 @@ log_referral(Operation *op) uint64_t connid; int32_t op_id; int32_t op_internal_id; - get_internal_conn_op(&connid, &op_id, &op_internal_id); + int32_t op_nested_count; + get_internal_conn_op(&connid, &op_id, &op_internal_id, &op_nested_count); slapi_log_access(LDAP_DEBUG_ARGS, - connid == 0 ? "conn=Internal(%" PRIu64 ") op=%d(%d) REFERRAL\n" : - "conn=%" PRIu64 " (Internal) op=%d(%d) REFERRAL\n", - connid, op_id, op_internal_id); + connid == 0 ? "conn=Internal(%" PRIu64 ") op=%d(%d)(%d) REFERRAL\n" : + "conn=%" PRIu64 " (Internal) op=%d(%d)(%d) REFERRAL\n", + connid, op_id, op_internal_id, op_nested_count); } } } diff --git a/ldap/servers/slapd/slapi-private.h b/ldap/servers/slapd/slapi-private.h index 21f883d..4161002 100644 --- a/ldap/servers/slapd/slapi-private.h +++ b/ldap/servers/slapd/slapi-private.h @@ -1176,7 +1176,7 @@ char *slapd_get_tmp_dir(void); typedef enum _slapi_op_nest_state { OP_STATE_NOTNESTED = 0, OP_STATE_NESTED = 1, - OP_STATE_UNNESTED = 2, + OP_STATE_PREV_NESTED = 2, } slapi_log_nest_state; @@ -1208,7 +1208,7 @@ const char *escape_string(const char *str, char buf[BUFSIZ]); const char *escape_string_with_punctuation(const char *str, char buf[BUFSIZ]); const char *escape_string_for_filename(const char *str, char buf[BUFSIZ]); void strcpy_unescape_value(char *d, const char *s); -void get_internal_conn_op (uint64_t *connid, int32_t *op_id, int32_t *op_internal_id); +void get_internal_conn_op (uint64_t *connid, int32_t *op_id, int32_t *op_internal_id, int32_t *op_nested_count); char *slapi_berval_get_string_copy(const struct berval *bval); /* lenstr stuff */ diff --git a/ldap/servers/slapd/thread_data.c b/ldap/servers/slapd/thread_data.c index ec145b5..7babe36 100644 --- a/ldap/servers/slapd/thread_data.c +++ b/ldap/servers/slapd/thread_data.c @@ -121,11 +121,9 @@ slapi_td_get_log_op_state() { /* - * Increment the internal operation count. Since internal operations - * can be nested via plugins calling plugins we need to keep track of - * this. If we become nested, and finally become unnested (back to the - * original internal op), then we have to bump the op id number twice - * for the next new (unnested) internal op. + * Increment the internal operation count. Unless we are nested, in that case + * do not update the internal op counter. If we just became "unnested" then + * update the state to keep the counters on track. */ void slapi_td_internal_op_start(void) @@ -142,38 +140,26 @@ slapi_td_internal_op_start(void) } } - /* increment the internal op id counter */ - op_state->op_int_id += 1; - - /* - * Bump the nested count so we can maintain our counts after plugins call - * plugins, etc. - */ + /* Bump the nested count */ op_state->op_nest_count += 1; - /* Now check for special cases in the nested count */ - if (op_state->op_nest_count == 2){ - /* We are now nested, mark it as so */ - /* THERE IS A BETTER WAY! We should track parent op structs instead! */ + if (op_state->op_nest_count > 1){ + /* We are nested */ op_state->op_nest_state = OP_STATE_NESTED; - } else if (op_state->op_nest_count == 1) { - /* - * Back to the beginning, but if we were previously nested then the - * internal op id count is off - */ - if (op_state->op_nest_state == OP_STATE_UNNESTED){ - /* We were nested but anymore, need to bump the internal id count again */ - op_state->op_nest_state = OP_STATE_NOTNESTED; /* reset nested state */ - op_state->op_int_id += 1; + } else { + /* We are not nested */ + op_state->op_int_id += 1; + if (op_state->op_nest_state == OP_STATE_PREV_NESTED) { + /* But we were just previously nested, so update the state */ + op_state->op_nest_state = OP_STATE_NOTNESTED; } } } /* - * Decrement the nested count. If we were actually nested (2 levels deep or more) - * then we need to lower the op id. If we were nested and are now unnested we need - * to mark this in the TD so on the next new internal op we set the its op id to the - * correct/expected/next-sequential value. + * Decrement the nested count. If we were nested and we are NOW unnested + * then we need to reset the state so on the next new internal op we set the + * counters to the correct/expected/next-sequential value. */ void slapi_td_internal_op_finish(void) @@ -190,24 +176,13 @@ slapi_td_internal_op_finish(void) return; } } - - if ( op_state->op_nest_count > 1 ){ - /* Nested op just finished, decr op id */ - op_state->op_int_id -= 1; - - if ( (op_state->op_nest_count - 1) == 1 ){ - /* - * Okay we are back to the beginning, We were nested but not - * anymore. So when we start the next internal op on this - * conn we need to double increment the internal op id to - * maintain the correct op id sequence. Set the nested state - * to "unnested". - */ - op_state->op_nest_state = OP_STATE_UNNESTED; - } - } /* decrement nested count */ op_state->op_nest_count -= 1; + + /* If we were nested, but NOT anymore, then update the state */ + if ( op_state->op_nest_state == OP_STATE_NESTED && op_state->op_nest_count == 1){ + op_state->op_nest_state = OP_STATE_PREV_NESTED; + } } void diff --git a/ldap/servers/slapd/util.c b/ldap/servers/slapd/util.c index ccc68ad..1a8df2f 100644 --- a/ldap/servers/slapd/util.c +++ b/ldap/servers/slapd/util.c @@ -1591,16 +1591,19 @@ slapi_create_errormsg( } void -get_internal_conn_op (uint64_t *connid, int32_t *op_id, int32_t *op_internal_id) { +get_internal_conn_op (uint64_t *connid, int32_t *op_id, int32_t *op_internal_id, int32_t *op_nested_count) { struct slapi_td_log_op_state_t *op_state = slapi_td_get_log_op_state(); if (op_state != NULL) { *connid = op_state->conn_id; *op_id = op_state->op_id; *op_internal_id = op_state->op_int_id; + *op_nested_count = op_state->op_nest_count; + } else { *connid = 0; *op_id = 0; *op_internal_id = 0; + *op_nested_count = 0; } }