From 90bf17995505dc1534827e50bda77358c0d5be28 Mon Sep 17 00:00:00 2001 From: Mark Reynolds Date: Aug 09 2018 19:11:33 +0000 Subject: Ticket 49029 - improve internal operations logging Description: This patch uses "local thread storage" to keep track of the connection and op id numbers for internal operations. This makes it easier to follow the access logs and know what connection is actually doing what. It also maintains its on operation id count for each internal operation. This adds complexity once internal ops start nesting (plugins calling plugins). To handle this two LTS variables were added to keep track of the nested level or count, and one to know once a series of nested operations are finally unnested/complete. This is needed to maintain the correct internal operation id counter correct and in sequence. Also organized the local thread storage initialization into a single function - there was no need to have separate functions. Thanks lkrispenz for improving the logging format, and providing the initial patch this was all based off of. https://pagure.io/389-ds-base/issue/49029 Reviewed by: tbordaz & lkrispen(Thanks!) --- diff --git a/ldap/admin/src/logconv.pl b/ldap/admin/src/logconv.pl index e36386e..f4808a1 100755 --- a/ldap/admin/src/logconv.pl +++ b/ldap/admin/src/logconv.pl @@ -2589,7 +2589,9 @@ sub parseLineNormal $hashes->{saslmech}->{$mech}--; } } - if (/ conn=Internal op=-1 / && !/ RESULT err=/){ $internalOpCount++; } + if (/ conn=Internal op=-1 / && !/ RESULT err=/){ $internalOpCount++; } # Old format + if (/ conn=Internal\(/ && !/ op=-1 / && !/ RESULT err=/){ $internalOpCount++;} # New format #1 + if (/ conn= *([0-9]+) \(Internal\) op=/ && !/ RESULT err=/){ $internalOpCount++;} # New format #2 if (/ ENTRY dn=/ ){ $entryOpCount++; } if (/ conn=/ && /op=/ && / REFERRAL/){ $referralCount++; } if (/ options=persistent/){$persistentSrchCount++;} diff --git a/ldap/servers/slapd/add.c b/ldap/servers/slapd/add.c index 9b53f15..65e9b56 100644 --- a/ldap/servers/slapd/add.c +++ b/ldap/servers/slapd/add.c @@ -267,7 +267,6 @@ slapi_add_internal(const char *idn, if (opresult != LDAP_SUCCESS) { goto done; } - result_pb = slapi_add_entry_internal(e, controls, dummy); done: @@ -404,7 +403,9 @@ add_internal_pb(Slapi_PBlock *pb) set_config_params(pb); /* perform the add operation */ + slapi_td_internal_op_start(); op_shared_add(pb); + slapi_td_internal_op_finish(); slapi_pblock_set(pb, SLAPI_PLUGIN_INTOP_RESULT, &opresult); @@ -463,9 +464,16 @@ op_shared_add(Slapi_PBlock *pb) slapi_entry_get_dn_const(e), proxystr ? proxystr : ""); } else { - slapi_log_access(LDAP_DEBUG_ARGS, "conn=%s op=%d ADD dn=\"%s\"\n", - LOG_INTERNAL_OP_CON_ID, - LOG_INTERNAL_OP_OP_ID, + 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, + 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, slapi_entry_get_dn_const(e)); } } diff --git a/ldap/servers/slapd/connection.c b/ldap/servers/slapd/connection.c index 188383b..5bc5217 100644 --- a/ldap/servers/slapd/connection.c +++ b/ldap/servers/slapd/connection.c @@ -520,10 +520,25 @@ connection_dispatch_operation(Connection *conn, Operation *op, Slapi_PBlock *pb) { int minssf = config_get_minssf(); int minssf_exclude_rootdse = 0; + uint64_t td_conn_id; + int32_t td_op_id; + int32_t td_internal_op = 0; + int32_t td_internal_nested_count = 0; + int32_t td_internal_nested_state = 0; #ifdef TCP_CORK int enable_nagle = config_get_nagle(); int pop_cork = 0; #endif + + /* Set the connid and op_id to be used by intenral op logging */ + td_conn_id = conn->c_connid; + td_op_id = op->o_opid; + slapi_td_set_val(SLAPI_TD_CONN_ID,(void *)&td_conn_id); + slapi_td_set_val(SLAPI_TD_OP_ID,(void *)&td_op_id); + slapi_td_set_val(SLAPI_TD_OP_INTERNAL_ID, (void *)&td_internal_op); + slapi_td_set_val(SLAPI_TD_OP_NESTED_COUNT, (void *)&td_internal_nested_count); + slapi_td_set_val(SLAPI_TD_OP_NESTED_STATE, (void *)&td_internal_nested_state); + /* Get the effective key length now since the first SSL handshake should be complete */ connection_set_ssl_ssf(conn); @@ -1804,6 +1819,12 @@ connection_threadmain() * threads devoted to this connection, and see if * there's more work to do right now on this conn. */ + int32_t def_val = 0; + slapi_td_set_val(SLAPI_TD_CONN_ID, NULL); + slapi_td_set_val(SLAPI_TD_OP_ID, NULL); + slapi_td_set_val(SLAPI_TD_OP_INTERNAL_ID, (void *)&def_val); + slapi_td_set_val(SLAPI_TD_OP_NESTED_COUNT, (void *)&def_val); + slapi_td_set_val(SLAPI_TD_OP_NESTED_STATE, (void *)&def_val); /* number of ops on this connection */ PR_AtomicIncrement(&conn->c_opscompleted); diff --git a/ldap/servers/slapd/delete.c b/ldap/servers/slapd/delete.c index 49cdab1..e740eb2 100644 --- a/ldap/servers/slapd/delete.c +++ b/ldap/servers/slapd/delete.c @@ -205,7 +205,9 @@ delete_internal_pb(Slapi_PBlock *pb) set_config_params(pb); /* perform delete operation */ + slapi_td_internal_op_start(); op_shared_delete(pb); + slapi_td_internal_op_finish(); slapi_pblock_set(pb, SLAPI_PLUGIN_INTOP_RESULT, &opresult); @@ -267,9 +269,16 @@ op_shared_delete(Slapi_PBlock *pb) slapi_sdn_get_dn(sdn), proxystr ? proxystr : ""); } else { - slapi_log_access(LDAP_DEBUG_ARGS, "conn=%s op=%d DEL dn=\"%s\"%s\n", - LOG_INTERNAL_OP_CON_ID, - LOG_INTERNAL_OP_OP_ID, + 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, + 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, + op_id, + op_internal_id, slapi_sdn_get_dn(sdn), proxystr ? proxystr : ""); } diff --git a/ldap/servers/slapd/main.c b/ldap/servers/slapd/main.c index 1108ad2..cb43b9d 100644 --- a/ldap/servers/slapd/main.c +++ b/ldap/servers/slapd/main.c @@ -1066,6 +1066,7 @@ main(int argc, char **argv) /* -sduloutre: compute_init() and entry_computed_attr_init() moved up */ if (mcfg.slapd_exemode != SLAPD_EXEMODE_REFERRAL) { + int32_t init_val = 0; int rc; Slapi_DN *sdn; @@ -1112,9 +1113,13 @@ main(int argc, char **argv) */ task_cleanup(); - /* init the thread data indexes */ - slapi_td_dn_init(); - slapi_td_plugin_lock_init(); + /* init the thread data indexes - need to initialize internal logging TD here for bootstrap startup */ + slapi_td_init(); + slapi_td_set_val(SLAPI_TD_CONN_ID, NULL); + slapi_td_set_val(SLAPI_TD_OP_ID, NULL); + slapi_td_set_val(SLAPI_TD_OP_INTERNAL_ID, (void *)&init_val); + slapi_td_set_val(SLAPI_TD_OP_NESTED_COUNT, (void *)&init_val); + slapi_td_set_val(SLAPI_TD_OP_NESTED_STATE, (void *)&init_val); /* * Initialize password storage in entry extension. diff --git a/ldap/servers/slapd/modify.c b/ldap/servers/slapd/modify.c index f2f6d17..01cf722 100644 --- a/ldap/servers/slapd/modify.c +++ b/ldap/servers/slapd/modify.c @@ -582,7 +582,9 @@ modify_internal_pb(Slapi_PBlock *pb) set_config_params(pb); /* perform modify operation */ + slapi_td_internal_op_start(); op_shared_modify(pb, pw_change, old_pw); + slapi_td_internal_op_finish(); /* free the normalized_mods don't forget to add this*/ slapi_pblock_get(pb, SLAPI_MODIFY_MODS, &normalized_mods); @@ -671,9 +673,16 @@ op_shared_modify(Slapi_PBlock *pb, int pw_change, char *old_pw) slapi_sdn_get_dn(sdn), proxystr ? proxystr : ""); } else { - slapi_log_access(LDAP_DEBUG_ARGS, "conn=%s op=%d MOD dn=\"%s\"%s\n", - LOG_INTERNAL_OP_CON_ID, - LOG_INTERNAL_OP_OP_ID, + 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, + 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, + op_id, + op_internal_id, slapi_sdn_get_dn(sdn), proxystr ? proxystr : ""); } diff --git a/ldap/servers/slapd/modrdn.c b/ldap/servers/slapd/modrdn.c index 9483aaf..e22997e 100644 --- a/ldap/servers/slapd/modrdn.c +++ b/ldap/servers/slapd/modrdn.c @@ -364,7 +364,9 @@ rename_internal_pb(Slapi_PBlock *pb) /* set actions taken to process the operation */ set_config_params(pb); + slapi_td_internal_op_start(); op_shared_rename(pb, 0 /* not passing ownership of args */); + slapi_td_internal_op_finish(); slapi_pblock_set(pb, SLAPI_PLUGIN_INTOP_RESULT, &opresult); @@ -474,10 +476,16 @@ op_shared_rename(Slapi_PBlock *pb, int passin_args) newsuperior ? newsuperior : "(null)", 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, - "conn=%s op=%d MODRDN dn=\"%s\" newrdn=\"%s\" newsuperior=\"%s\"%s\n", - LOG_INTERNAL_OP_CON_ID, - LOG_INTERNAL_OP_OP_ID, + 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, dn, newrdn ? newrdn : "(null)", newsuperior ? newsuperior : "(null)", diff --git a/ldap/servers/slapd/opshared.c b/ldap/servers/slapd/opshared.c index 74f2c24..9ec758d 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=%s 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_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; + } } } @@ -339,8 +354,9 @@ op_shared_search(Slapi_PBlock *pb, int send_result) proxystr ? proxystr : ""); } else { slapi_log_access(LDAP_DEBUG_ARGS, fmtstr, - LOG_INTERNAL_OP_CON_ID, - LOG_INTERNAL_OP_OP_ID, + connid, + op_id, + op_internal_id, normbase, scope, fstr, attrliststr, flag_psearch ? " options=persistent" : "", diff --git a/ldap/servers/slapd/plugin_internal_op.c b/ldap/servers/slapd/plugin_internal_op.c index f6bbafb..9da266b 100644 --- a/ldap/servers/slapd/plugin_internal_op.c +++ b/ldap/servers/slapd/plugin_internal_op.c @@ -377,12 +377,14 @@ seq_internal_callback_pb(Slapi_PBlock *pb, void *callback_data, plugin_result_ca /* set common parameters */ set_common_params(pb); + slapi_td_internal_op_start(); if (be->be_seq != NULL) { rc = (*be->be_seq)(pb); } else { send_ldap_result(pb, LDAP_UNWILLING_TO_PERFORM, NULL, "Function not implemented", 0, NULL); rc = 0; } + slapi_td_internal_op_finish(); slapi_ch_free_string(&attrname); slapi_ch_free_string(&val); @@ -724,7 +726,9 @@ search_internal_callback_pb(Slapi_PBlock *pb, void *callback_data, plugin_result * memory so we need to keep track of * changed base search strings */ + slapi_td_internal_op_start(); op_shared_search(pb, 1); + slapi_td_internal_op_finish(); slapi_pblock_get(pb, SLAPI_SEARCH_FILTER, &filter); diff --git a/ldap/servers/slapd/result.c b/ldap/servers/slapd/result.c index d9f431c..0570f31 100644 --- a/ldap/servers/slapd/result.c +++ b/ldap/servers/slapd/result.c @@ -1911,6 +1911,11 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries int pr_idx = -1; int pr_cookie = -1; uint32_t operation_notes; + uint64_t connid; + int32_t op_id; + int32_t op_internal_id; + + get_internal_conn_op(&connid, &op_id, &op_internal_id); slapi_pblock_get(pb, SLAPI_PAGED_RESULTS_INDEX, &pr_idx); slapi_pblock_get(pb, SLAPI_PAGED_RESULTS_COOKIE, &pr_cookie); @@ -1941,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. @@ -1957,12 +1964,14 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries etime, 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=%s op=%d RESULT err=%d" - " tag=%" BERTAG_T " nentries=%d etime=%s%s%s" - ", SASL bind in progress\n", - LOG_INTERNAL_OP_CON_ID, - LOG_INTERNAL_OP_OP_ID, + 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, err, tag, nentries, etime, notes_str, csn_str); @@ -1986,12 +1995,13 @@ 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=%s op=%d RESULT err=%d" - " tag=%" BERTAG_T " nentries=%d etime=%s%s%s" - " dn=\"%s\"\n", - LOG_INTERNAL_OP_CON_ID, - LOG_INTERNAL_OP_OP_ID, + 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, err, tag, nentries, etime, notes_str, csn_str, dn ? dn : ""); @@ -2010,12 +2020,13 @@ 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=%s op=%d RESULT err=%d" - " tag=%" BERTAG_T " nentries=%d etime=%s%s%s" - " pr_idx=%d pr_cookie=%d \n", - LOG_INTERNAL_OP_CON_ID, - LOG_INTERNAL_OP_OP_ID, + 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, err, tag, nentries, etime, notes_str, csn_str, pr_idx, pr_cookie); @@ -2043,11 +2054,13 @@ 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=%s op=%d RESULT err=%d" - " tag=%" BERTAG_T " nentries=%d etime=%s%s%s\n", - LOG_INTERNAL_OP_CON_ID, - LOG_INTERNAL_OP_OP_ID, + 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, err, tag, nentries, etime, notes_str, csn_str); @@ -2101,8 +2114,16 @@ log_entry(Operation *op, Slapi_Entry *e) slapi_entry_get_dn_const(e)); } else { if (config_get_accesslog_level() & LDAP_DEBUG_STATS2) { - slapi_log_access(LDAP_DEBUG_ARGS, "conn=%s op=%d ENTRY dn=\"%s\"\n", - LOG_INTERNAL_OP_CON_ID, LOG_INTERNAL_OP_OP_ID, + 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, + 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, slapi_entry_get_dn_const(e)); } } @@ -2121,8 +2142,14 @@ log_referral(Operation *op) op->o_connid, op->o_opid); } else { if (config_get_accesslog_level() & LDAP_DEBUG_STATS2) { - slapi_log_access(LDAP_DEBUG_ARGS, "conn=%s op=%d REFERRAL\n", - LOG_INTERNAL_OP_CON_ID, LOG_INTERNAL_OP_OP_ID); + 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, + connid == 0 ? "conn=Internal(%" PRIu64 ") op=%d(%d) REFERRAL\n" : + "conn=%" PRIu64 " (Internal) op=%d(%d) REFERRAL\n", + connid, op_id, op_internal_id); } } } diff --git a/ldap/servers/slapd/slapi-plugin.h b/ldap/servers/slapd/slapi-plugin.h index e862382..0244e30 100644 --- a/ldap/servers/slapd/slapi-plugin.h +++ b/ldap/servers/slapd/slapi-plugin.h @@ -5580,23 +5580,6 @@ int slapi_apib_release(void **api); /**** End of API broker interface. *******************************************/ -/* thread_data.c */ -int slapi_td_init(int indexType); -int slapi_td_set_val(int indexType, void *value); -void slapi_td_get_val(int indexType, void **value); -int slapi_td_dn_init(void); -int slapi_td_set_dn(char *dn); -void slapi_td_get_dn(char **dn); -int slapi_td_plugin_lock_init(void); -int slapi_td_get_plugin_locked(void); -int slapi_td_set_plugin_locked(void); -int slapi_td_set_plugin_unlocked(void); - - -/* Thread Local Storage Index Types */ -#define SLAPI_TD_REQUESTOR_DN 1 -#define SLAPI_TD_PLUGIN_LIST_LOCK 2 - /* * routines for dealing with controls */ diff --git a/ldap/servers/slapd/slapi-private.h b/ldap/servers/slapd/slapi-private.h index 9c90dfb..8fa62b4 100644 --- a/ldap/servers/slapd/slapi-private.h +++ b/ldap/servers/slapd/slapi-private.h @@ -1172,13 +1172,36 @@ int slapd_security_library_is_initialized(void); int slapd_nss_is_initialized(void); char *slapd_get_tmp_dir(void); +/* thread-data.c */ +int slapi_td_init(void); +int slapi_td_set_val(int indexType, void *value); +void slapi_td_get_val(int indexType, void **value); +int slapi_td_dn_init(void); +int slapi_td_set_dn(char *dn); +void slapi_td_get_dn(char **dn); +int slapi_td_plugin_lock_init(void); +int slapi_td_get_plugin_locked(void); +int slapi_td_set_plugin_locked(void); +int slapi_td_set_plugin_unlocked(void); +void slapi_td_internal_op_start(void); +void slapi_td_internal_op_finish(void); + +/* Thread Local Storage Index Types - thread_data.c */ +#define SLAPI_TD_REQUESTOR_DN 1 +#define SLAPI_TD_PLUGIN_LIST_LOCK 2 +#define SLAPI_TD_CONN_ID 3 +#define SLAPI_TD_OP_ID 4 +#define SLAPI_TD_OP_INTERNAL_ID 5 +#define SLAPI_TD_OP_NESTED_COUNT 6 +#define SLAPI_TD_OP_NESTED_STATE 7 + /* util.c */ #include /* GGOODREPL - For BUFSIZ, below, gak */ 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); 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 d473710..5c89efe 100644 --- a/ldap/servers/slapd/thread_data.c +++ b/ldap/servers/slapd/thread_data.c @@ -19,6 +19,16 @@ void td_dn_destructor(void *priv); */ static PRUintn td_requestor_dn; /* TD_REQUESTOR_DN */ static PRUintn td_plugin_list; /* SLAPI_TD_PLUGIN_LIST_LOCK - integer set to 1 or zero */ +static PRUintn td_conn_id; +static PRUintn td_op_id; +static PRUintn td_op_internal_id; +static PRUintn td_op_internal_nested_state; +static PRUintn td_op_internal_nested_count; + +/* defines for internal logging */ +#define NOTNESTED 0 +#define NESTED 1 +#define UNNESTED 2 /* * Index types defined in slapi-plugin.h @@ -43,23 +53,50 @@ static PRUintn td_plugin_list; /* SLAPI_TD_PLUGIN_LIST_LOCK - integer set to 1 */ int -slapi_td_init(int indexType) +slapi_td_init(void) { - switch (indexType) { - case SLAPI_TD_REQUESTOR_DN: - if (PR_NewThreadPrivateIndex(&td_requestor_dn, td_dn_destructor) == PR_FAILURE) { - return PR_FAILURE; - } - break; - case SLAPI_TD_PLUGIN_LIST_LOCK: - if (PR_NewThreadPrivateIndex(&td_plugin_list, NULL) == PR_FAILURE) { - return PR_FAILURE; - } - break; + int32_t init_val = 0; - default: + if (PR_NewThreadPrivateIndex(&td_requestor_dn, td_dn_destructor) == PR_FAILURE) { + slapi_log_err(SLAPI_LOG_CRIT, "slapi_td_init", "Failed it create private thread index for td_requestor_dn/td_dn_destructor\n"); + return PR_FAILURE; + } + + if (PR_NewThreadPrivateIndex(&td_plugin_list, NULL) == PR_FAILURE) { + slapi_log_err(SLAPI_LOG_CRIT, "slapi_td_init", "Failed it create private thread index for td_plugin_list\n"); + return PR_FAILURE; + } + + if(PR_NewThreadPrivateIndex(&td_conn_id, NULL) == PR_FAILURE){ + slapi_log_err(SLAPI_LOG_CRIT, "slapi_td_init", "Failed it create private thread index for td_conn_id\n"); + return PR_FAILURE; + } + slapi_td_set_val(SLAPI_TD_CONN_ID, (void *)&init_val); + + if(PR_NewThreadPrivateIndex(&td_op_id, NULL) == PR_FAILURE){ + slapi_log_err(SLAPI_LOG_CRIT, "slapi_td_init", "Failed it create private thread index for td_op_id\n"); + return PR_FAILURE; + } + slapi_td_set_val(SLAPI_TD_OP_ID, (void *)&init_val); + + if(PR_NewThreadPrivateIndex(&td_op_internal_id, NULL) == PR_FAILURE){ + slapi_log_err(SLAPI_LOG_CRIT, "slapi_td_init", "Failed it create private thread index for td_op_internal_id\n"); + return PR_FAILURE; + } + slapi_td_set_val(SLAPI_TD_OP_INTERNAL_ID, (void *)&init_val); + + if(PR_NewThreadPrivateIndex(&td_op_internal_nested_count, NULL) == PR_FAILURE){ + slapi_log_err(SLAPI_LOG_CRIT, "slapi_td_init", "Failed it create private thread index for td_op_internal_nested_count\n"); + return PR_FAILURE; + } + slapi_td_set_val(SLAPI_TD_OP_NESTED_COUNT, (void *)&init_val); + + if(PR_NewThreadPrivateIndex(&td_op_internal_nested_state, NULL) == PR_FAILURE){ + slapi_log_err(SLAPI_LOG_CRIT, "slapi_td_init", "Failed it create private thread index for td_op_internal_nested_state\n"); return PR_FAILURE; } + slapi_td_set_val(SLAPI_TD_OP_NESTED_STATE, (void *)&init_val); + return PR_SUCCESS; } @@ -89,6 +126,51 @@ slapi_td_set_val(int indexType, void *value) return PR_FAILURE; } break; + case SLAPI_TD_CONN_ID: + if(td_conn_id){ + if(PR_SetThreadPrivate(td_conn_id, value) == PR_FAILURE){ + return PR_FAILURE; + } + } else { + return PR_FAILURE; + } + break; + case SLAPI_TD_OP_ID: + if(td_op_id){ + if(PR_SetThreadPrivate(td_op_id, value) == PR_FAILURE){ + return PR_FAILURE; + } + } else { + return PR_FAILURE; + } + break; + case SLAPI_TD_OP_INTERNAL_ID: + if(td_op_internal_id){ + if(PR_SetThreadPrivate(td_op_internal_id, value) == PR_FAILURE){ + return PR_FAILURE; + } + } else { + return PR_FAILURE; + } + break; + case SLAPI_TD_OP_NESTED_COUNT: + if(td_op_internal_nested_count){ + if(PR_SetThreadPrivate(td_op_internal_nested_count, value) == PR_FAILURE){ + return PR_FAILURE; + } + } else { + return PR_FAILURE; + } + break; + case SLAPI_TD_OP_NESTED_STATE: + if(td_op_internal_nested_state){ + if(PR_SetThreadPrivate(td_op_internal_nested_state, value) == PR_FAILURE){ + return PR_FAILURE; + } + } else { + return PR_FAILURE; + } + break; default: return PR_FAILURE; } @@ -117,6 +199,41 @@ slapi_td_get_val(int indexType, void **value) *value = 0; } break; + case SLAPI_TD_CONN_ID: + if(td_conn_id){ + *value = PR_GetThreadPrivate(td_conn_id); + } else { + *value = 0; + } + break; + case SLAPI_TD_OP_ID: + if(td_op_id){ + *value = PR_GetThreadPrivate(td_op_id); + } else { + *value = 0; + } + break; + case SLAPI_TD_OP_INTERNAL_ID: + if(td_op_internal_id){ + *value = PR_GetThreadPrivate(td_op_internal_id); + } else { + *value = 0; + } + break; + case SLAPI_TD_OP_NESTED_COUNT: + if(td_op_internal_nested_count){ + *value = PR_GetThreadPrivate(td_op_internal_nested_count); + } else { + *value = 0; + } + break; + case SLAPI_TD_OP_NESTED_STATE: + if(td_op_internal_nested_state){ + *value = PR_GetThreadPrivate(td_op_internal_nested_state); + } else { + *value = 0; + } + break; default: *value = NULL; return; @@ -129,16 +246,6 @@ slapi_td_get_val(int indexType, void **value) /* plugin list locking */ int -slapi_td_plugin_lock_init() -{ - if (slapi_td_init(SLAPI_TD_PLUGIN_LIST_LOCK) == PR_FAILURE) { - return PR_FAILURE; - } - - return PR_SUCCESS; -} - -int slapi_td_set_plugin_locked() { int val = 12345; @@ -175,16 +282,6 @@ slapi_td_get_plugin_locked() /* requestor dn */ int -slapi_td_dn_init() -{ - if (slapi_td_init(SLAPI_TD_REQUESTOR_DN) == PR_FAILURE) { - return PR_FAILURE; - } - - return PR_SUCCESS; -} - -int slapi_td_set_dn(char *value) { if (slapi_td_set_val(SLAPI_TD_REQUESTOR_DN, (void *)value) == PR_FAILURE) { @@ -200,6 +297,113 @@ slapi_td_get_dn(char **value) slapi_td_get_val(SLAPI_TD_REQUESTOR_DN, (void **)value); } +/* + * 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. + */ +void +slapi_td_internal_op_start(void) +{ + int32_t initial_count = 1; + int32_t *id_count_ptr = NULL; + int32_t *nested_state_ptr = NULL; + int32_t *nested_count_ptr = NULL; + uint64_t *connid = NULL; + + slapi_td_get_val(SLAPI_TD_CONN_ID, (void **)&connid); + if (connid == NULL){ + /* No connection id, just return */ + return; + } + + /* increment the internal op id counter */ + slapi_td_get_val(SLAPI_TD_OP_INTERNAL_ID, (void **)&id_count_ptr); + if (id_count_ptr == NULL){ + id_count_ptr = &initial_count; + } else { + (*id_count_ptr)++; + } + + /* + * Bump the nested count so we can maintain our counts after plugins call + * plugins, etc. + */ + slapi_td_get_val(SLAPI_TD_OP_NESTED_COUNT, (void **)&nested_count_ptr); + (*nested_count_ptr)++; + + /* Now check for special cases in the nested count */ + if (*nested_count_ptr == 2){ + /* We are now nested, mark it as so */ + slapi_td_get_val(SLAPI_TD_OP_NESTED_STATE, (void **)&nested_state_ptr); + *nested_state_ptr = NESTED; + slapi_td_set_val(SLAPI_TD_OP_NESTED_STATE, (void *)nested_state_ptr); + } else if (*nested_count_ptr == 1) { + /* + * Back to the beginning, but if we were previously nested then the + * internal op id count is off + */ + slapi_td_get_val(SLAPI_TD_OP_NESTED_STATE, (void **)&nested_state_ptr); + if (*nested_state_ptr == UNNESTED){ + /* We were nested but anymore, need to bump the internal id count again */ + *nested_state_ptr = NOTNESTED; /* reset nested state */ + slapi_td_set_val(SLAPI_TD_OP_NESTED_STATE, (void *)nested_state_ptr); + (*id_count_ptr)++; + } + } + slapi_td_set_val(SLAPI_TD_OP_NESTED_COUNT, (void *)nested_count_ptr); + slapi_td_set_val(SLAPI_TD_OP_INTERNAL_ID, (void *)id_count_ptr); +} + +/* + * 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. + */ +void +slapi_td_internal_op_finish(void) +{ + int32_t *nested_count_ptr = NULL; + int32_t *nested_state_ptr = NULL; + int32_t *id_count_ptr = NULL; + uint64_t *connid = NULL; + + slapi_td_get_val(SLAPI_TD_OP_INTERNAL_ID, (void **)&connid); + if (connid == NULL){ + /* No connection id, just return */ + return; + } + + slapi_td_get_val(SLAPI_TD_OP_NESTED_COUNT, (void **)&nested_count_ptr); + if (nested_count_ptr){ + if ( *nested_count_ptr > 1 ){ + /* Nested op just finished, decr op id */ + slapi_td_get_val(SLAPI_TD_OP_INTERNAL_ID, (void **)&id_count_ptr); + if (id_count_ptr){ + (*id_count_ptr)--; + slapi_td_set_val(SLAPI_TD_OP_INTERNAL_ID, (void *)id_count_ptr); + } + if ( (*nested_count_ptr - 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". + */ + slapi_td_get_val(SLAPI_TD_OP_NESTED_STATE, (void **)&nested_state_ptr); + (*nested_state_ptr) = UNNESTED; + slapi_td_set_val(SLAPI_TD_OP_NESTED_STATE, (void *)nested_state_ptr); + } + } + /* decrement nested count */ + (*nested_count_ptr)--; + slapi_td_set_val(SLAPI_TD_OP_NESTED_COUNT, (void *)nested_count_ptr); + } +} /* * Destructor Functions @@ -210,3 +414,4 @@ td_dn_destructor(void *priv) { slapi_ch_free((void **)&priv); } + diff --git a/ldap/servers/slapd/util.c b/ldap/servers/slapd/util.c index 1be215b..329fa8b 100644 --- a/ldap/servers/slapd/util.c +++ b/ldap/servers/slapd/util.c @@ -1589,3 +1589,33 @@ slapi_create_errormsg( va_end(ap); } } + +void +get_internal_conn_op (uint64_t *connid, int32_t *op_id, int32_t *op_internal_id) +{ + uint64_t default_id = 0; + uint64_t *td_conn; + + slapi_td_get_val(SLAPI_TD_CONN_ID,(void **)&td_conn); + if (td_conn) { + int32_t *td_op; + int32_t *td_internal_op; + *connid = *td_conn; + slapi_td_get_val(SLAPI_TD_OP_ID,(void **)&td_op); + if (td_op) { + *op_id = *td_op; + } else { + *op_id = default_id; + } + slapi_td_get_val(SLAPI_TD_OP_INTERNAL_ID,(void **)&td_internal_op); + if (td_internal_op){ + *op_internal_id = *td_internal_op; + } else { + *op_internal_id = default_id; + } + } else { + *connid = default_id; + *op_id = default_id; + *op_internal_id = default_id; + } +}