PR#25: 1694263 - ipa-server-install --setup-kra deadlocks while installing the KRA - slapi-nis

slapi-nis

#25 1694263 - ipa-server-install --setup-kra deadlocks while installing the KRA

Merged 5 years ago by abbra. Opened 5 years ago by tbordaz.

tbordaz/slapi-nis bz_1694263 into master

Bug 1694263: On some 'cn=config' updates bepost_op are not called that leads to lock leak

Thierry Bordaz • 5 years ago

52fd159

Bug 1694263: improve debug msg to match pstack threadId

Thierry Bordaz • 5 years ago

5e6953c

Bug 1694263: Fix thread private variable initialization

Thierry Bordaz • 5 years ago

1ccbfe2

src/back-sch.c

file modified

+90 -47

		`@@ -2303,10 +2303,37 @@`
		`slapi_pblock_get(pb, SLAPI_PLUGIN_PRIVATE, &state);`
		`return state->use_be_txns ? backend_write_cb(pb, state) : 0;`
		`}`
		`+ static PRBool`
		`+ backend_be_write_ignore(Slapi_PBlock *pb)`
		`+ {`
		`+ char *dn = NULL;`
		`+ Slapi_DN *target_sdn = NULL;`
		`+ int check;`
		`+ int i = 0;`
		`+ PRBool ignore = PR_FALSE;`
		`+`
		`+ /* Check if the target DN is a subordinates of`
		`+ * on of the ignored containers`
		`+ */`
		`+ slapi_pblock_get(pb, SLAPI_ORIGINAL_TARGET, &dn);`
		`+ target_sdn = slapi_sdn_new_dn_byval(dn);`
		`+`
		`+ for (i = 0; ignored_containers_sdn[i]; i++) {`
		`+ check = slapi_sdn_issuffix(target_sdn, ignored_containers_sdn[i]);`
		`+ if (check != 0) {`
		`+ /* This entry is an ignored container */`
		`+ ignore = PR_TRUE;`
		`+ break;`
		`+ }`
		`+ }`
		`+ slapi_sdn_free(&target_sdn);`
		`+ return ignore;`
		`+ }`
		`+`

		`static int`
		`backend_be_pre_write_cb(Slapi_PBlock *pb) {`
		`- int ret;`
		`+ int ret = 0;`
		`int lock_status;`
		`int lock_count;`
		`struct plugin_state *state;`
		`@@ -2323,6 +2350,14 @@`
		`if (rw_monitor_enabled() == MAP_MONITOR_DISABLED) {`
		`return 0;`
		`}`
		`+ if (backend_be_write_ignore(pb)) {`
		`+ #if DEBUG_MAP_LOCK`
		`+ slapi_log_error(SLAPI_LOG_FATAL, "schemacompat",`
		`+ "backend_be_pre_write_cb: (%p) operation is not impacting schema compat\n", PR_MyThreadId(), 1);`
		`+ #endif`
		`+ return 0;`
		`+ }`
		`+`


		`wrap_inc_call_level();`
		`@@ -2334,6 +2369,7 @@`
		`}`

		`if (lock_status == MAP_RWLOCK_FREE) {`
		`+ /* This thread does not hold the map lock */`
		`set_plugin_monitor_count(1);`

		`if (plugin_wrlock() == 0) {`
		`@@ -2345,14 +2381,14 @@`
		`}`
		`#if DEBUG_MAP_LOCK`
		`slapi_log_error(SLAPI_LOG_FATAL, "schemacompat",`
		`- "backend_be_pre_write_cb: (%p) MAP_RWLOCK_FREE -> MAP_WLOCK_HELD : count=%d\n", PR_GetCurrentThread(), 1);`
		`+ "backend_be_pre_write_cb: (%p) MAP_RWLOCK_FREE -> MAP_WLOCK_HELD : count=%d\n", (void *) PR_MyThreadId(), 1);`
		`#endif`
		`} else {`
		`set_plugin_monitor_count(lock_count + 1);`
		`#if DEBUG_MAP_LOCK`
		`slapi_log_error(SLAPI_LOG_FATAL, "schema-compat",`
		`"backend_be_pre_write_cb: (%p) %s --> MAP_WLOCK_HELD : count=%d\n",`
		`- PR_GetCurrentThread(),`
		`+ (void *) PR_MyThreadId(),`
		`(lock_status == MAP_WLOCK_HELD) ? "MAP_WLOCK_HELD": "MAP_RLOCK_HELD",`
		`lock_count + 1);`
		`#endif`
		`@@ -2389,12 +2425,12 @@`
		`static int`
		`backend_be_post_write_cb(Slapi_PBlock *pb)`
		`{`
		`- int ret;`
		`- int lock_status;`
		`- int lock_count;`
		`- struct plugin_state *state;`
		`+ int ret = 0;`
		`+ int lock_status;`
		`+ int lock_count;`
		`+ struct plugin_state *state;`

		`- slapi_pblock_get(pb, SLAPI_PLUGIN_PRIVATE, &state);`
		`+ slapi_pblock_get(pb, SLAPI_PLUGIN_PRIVATE, &state);`

		`if (wrap_get_call_level() > 0) {`
		`return 0;`
		`@@ -2403,53 +2439,60 @@`
		`/* No data to serve yet */`
		`return 0;`
		`}`
		`- if (rw_monitor_enabled() == MAP_MONITOR_DISABLED) {`
		`- return 0;`
		`- }`
		`+ if (rw_monitor_enabled() == MAP_MONITOR_DISABLED) {`
		`+ return 0;`
		`+ }`
		`+ if (backend_be_write_ignore(pb)) {`
		`+ #if DEBUG_MAP_LOCK`
		`+ slapi_log_error(SLAPI_LOG_FATAL, "schemacompat",`
		`+ "backend_be_post_write_cb: (%p) operation was not impacting schema compat\n", PR_MyThreadId(), 1);`
		`+ #endif`
		`+ return 0;`
		`+ }`

		`wrap_inc_call_level();`

		`- lock_status = get_plugin_monitor_status();`
		`- lock_count = get_plugin_monitor_count();`
		`- if (lock_status == MAP_RWLOCK_UNINIT) {`
		`- return 0;`
		`- }`
		`+ lock_status = get_plugin_monitor_status();`
		`+ lock_count = get_plugin_monitor_count();`
		`+ if (lock_status == MAP_RWLOCK_UNINIT) {`
		`+ return 0;`
		`+ }`

		`- if (lock_count == 1) {`
		`- set_plugin_monitor_status(MAP_RWLOCK_FREE);`
		`- if (plugin_unlock() == 0) {`
		`- ret = 0;`
		`- } else {`
		`- slapi_log_error(SLAPI_LOG_PLUGIN, state->plugin_desc->spd_id,`
		`- "backend_be_post_write_cb: unable to release write lock\n");`
		`- ret = -1;`
		`- }`
		`- #if DEBUG_MAP_LOCK`
		`- slapi_log_error(SLAPI_LOG_FATAL, "schema-compat",`
		`- "backend_be_post_write_cb: (%p) %s --> MAP_RWLOCK_FREE : count=%d\n",`
		`- PR_GetCurrentThread(),`
		`- (lock_status == MAP_WLOCK_HELD) ? "MAP_WLOCK_HELD" : (lock_status == MAP_RLOCK_HELD) ? "MAP_RLOCK_HELD" : "MAP_RWLOCK_FREE",`
		`- 0);`
		`- #endif`
		`+ if (lock_count == 1) {`
		`+ set_plugin_monitor_status(MAP_RWLOCK_FREE);`
		`+ if (plugin_unlock() == 0) {`
		`+ ret = 0;`
		`+ } else {`
		`+ slapi_log_error(SLAPI_LOG_PLUGIN, state->plugin_desc->spd_id,`
		`+ "backend_be_post_write_cb: unable to release write lock\n");`
		`+ ret = -1;`
		`}`
		`- if (lock_count >= 1) {`
		`- set_plugin_monitor_count(lock_count - 1);`
		`#if DEBUG_MAP_LOCK`
		`- if (lock_count > 1) {`
		`- slapi_log_error(SLAPI_LOG_FATAL, "schema-compat",`
		`- "backend_be_post_write_cb: (%p) keep %s : count=%d\n",`
		`- PR_GetCurrentThread(),`
		`- (lock_status == MAP_WLOCK_HELD) ? "MAP_WLOCK_HELD" : (lock_status == MAP_RLOCK_HELD) ? "MAP_RLOCK_HELD" : "MAP_RWLOCK_FREE",`
		`- lock_count - 1);`
		`- } else {`
		`- slapi_log_error(SLAPI_LOG_FATAL, "schema-compat",`
		`- "backend_be_post_write_cb: (%p) is now %s : count=%d\n",`
		`- PR_GetCurrentThread(),`
		`- "MAP_RWLOCK_FREE",`
		`- lock_count - 1);`
		`- }`
		`+ slapi_log_error(SLAPI_LOG_FATAL, "schema-compat",`
		`+ "backend_be_post_write_cb: (%p) %s --> MAP_RWLOCK_FREE : count=%d\n",`
		`+ (void *) PR_MyThreadId(),`
		`+ (lock_status == MAP_WLOCK_HELD) ? "MAP_WLOCK_HELD" : (lock_status == MAP_RLOCK_HELD) ? "MAP_RLOCK_HELD" : "MAP_RWLOCK_FREE",`
		`+ 0);`
		`#endif`
		`+ }`
		`+ if (lock_count >= 1) {`
		`+ set_plugin_monitor_count(lock_count - 1);`
		`+ #if DEBUG_MAP_LOCK`
		`+ if (lock_count > 1) {`
		`+ slapi_log_error(SLAPI_LOG_FATAL, "schema-compat",`
		`+ "backend_be_post_write_cb: (%p) keep %s : count=%d\n",`
		`+ (void *) PR_MyThreadId(),`
		`+ (lock_status == MAP_WLOCK_HELD) ? "MAP_WLOCK_HELD" : (lock_status == MAP_RLOCK_HELD) ? "MAP_RLOCK_HELD" : "MAP_RWLOCK_FREE",`
		`+ lock_count - 1);`
		`+ } else {`
		`+ slapi_log_error(SLAPI_LOG_FATAL, "schema-compat",`
		`+ "backend_be_post_write_cb: (%p) is now %s : count=%d\n",`
		`+ (void *) PR_MyThreadId(),`
		`+ "MAP_RWLOCK_FREE",`
		`+ lock_count - 1);`
		`}`
		`+ #endif`
		`+ }`
		`wrap_dec_call_level();`

		`return ret;`

src/back-shr.c

file modified

+135 -30

		`@@ -37,6 +37,7 @@`
		`#endif`

		`#include <rpc/xdr.h>`
		`+ #include <nspr4/prtypes.h>`
		`#include "../yp/yp.h"`

		`#ifdef HAVE_TCPD_H`
		`@@ -2867,31 +2868,86 @@`
		`return 0;`
		`}`

		`- static unsigned int thread_dummy;`
		`+ int`
		`+ PR_MyThreadId(void)`
		`+ {`
		`+ PRThread *thr = PR_GetCurrentThread();`
		`+ PRUint32 myself = PR_GetThreadID(thr);`
		`+ return myself;`
		`+ }`
		`+ PRBool use_lock_status = PR_FALSE;`
		`static unsigned int thread_plugin_lock_status;`
		`- static int thread_plugin_lock_count;`
		`+ PRBool use_lock_count = PR_FALSE;`
		`+ static unsigned int thread_plugin_lock_count;`
		`+ /*`
		`+ * https://developer.mozilla.org/en-US/docs/Mozilla/Projects/NSPR/Reference/PR_NewThreadPrivateIndex`
		`+ * It is called each time:`
		`+ * - PR_SetThreadPrivate is call with a not NULL private value`
		`+ * - on thread exit`
		`+ */`
		`+ static void`
		`+ lock_status_free(void *ptr)`
		`+ {`
		`+ int *lock_status = ptr;`
		`+ if (lock_status) {`
		`+ slapi_ch_free((void **)&lock_status);`
		`+ }`
		`+ }`
		`+ static void`
		`+ lock_count_free(void *ptr)`
		`+ {`
		`+ int *lock_count = ptr;`
		`+ if (lock_count) {`
		`+ slapi_ch_free((void **)&lock_count);`
		`+ }`
		`+ }`

		`+ /* This is used to ignore some write operations`
		`+ * if they target subordinates entry of ignored containers`
		`+ */`
		`+ Slapi_DN **ignored_containers_sdn = NULL;`
		`void`
		`init_map_lock(void)`
		`{`
		`+ #if DEBUG_MAP_LOCK`
		`/* The plugin lock is initialized as free */`
		`slapi_log_error(SLAPI_LOG_FATAL, "init_plugin_lock",`
		`- "thread_id = %p\n", PR_GetCurrentThread());`
		`+ "thread_id = %p\n", PR_MyThreadId());`
		`+ #endif`
		`+ if (ignored_containers_sdn == NULL) {`
		`+ /* allocates ignored_containers_sdn of Slapi_DN* only once`
		`+ * It will be used later in be_pre/post_write_cb`
		`+ */`
		`+ int cnt;`
		`+ char *ignored_containers[3] = { "cn=config", "cn=schema", NULL};`
		`+`
		`+ for (cnt = 0; ignored_containers[cnt]; cnt++);`
		`+ ignored_containers_sdn = (Slapi_DN *) slapi_ch_calloc(cnt + 1, sizeof(Slapi_DN ));`
		`+`
		`+ for (cnt = 0; ignored_containers[cnt]; cnt++) {`
		`+ ignored_containers_sdn[cnt] = slapi_sdn_new_dn_byval(ignored_containers[cnt]);`
		`+ }`
		`+ }`

		`- PR_NewThreadPrivateIndex (&thread_dummy, NULL);`
		`- PR_NewThreadPrivateIndex(&thread_plugin_lock_status, NULL);`
		`- PR_NewThreadPrivateIndex(&thread_plugin_lock_count, NULL);`
		`+ if (PR_NewThreadPrivateIndex(&thread_plugin_lock_status, lock_status_free) == PR_SUCCESS) {`
		`+ use_lock_status = PR_TRUE;`
		`+ }`
		`+ if (PR_NewThreadPrivateIndex(&thread_plugin_lock_count, lock_count_free) == PR_SUCCESS) {`
		`+ use_lock_count = PR_TRUE;`
		`+ }`

		`+ #if DEBUG_MAP_LOCK`
		`slapi_log_error(SLAPI_LOG_FATAL, "init_plugin_lock",`
		`"thread_plugin_lock_status = %d\n", thread_plugin_lock_status);`
		`slapi_log_error(SLAPI_LOG_FATAL, "init_map_lock",`
		`"thread_plugin_lock_count = %d\n", thread_plugin_lock_count);`
		`+ #endif`
		`}`

		`int`
		`rw_monitor_enabled(void)`
		`{`
		`- if (thread_plugin_lock_status)`
		`+ if (use_lock_status)`
		`return (int) MAP_MONITOR_ENABLED;`
		`else`
		`return (int) MAP_MONITOR_DISABLED;`
		`@@ -2902,13 +2958,27 @@`
		`{`
		`int ret;`

		`- if (thread_plugin_lock_status)`
		`- ret = (int) PR_GetThreadPrivate(thread_plugin_lock_status);`
		`- else`
		`+ if (use_lock_status) {`
		`+ int *lock_status_p;`
		`+ lock_status_p = (int *) PR_GetThreadPrivate(thread_plugin_lock_status);`
		`+ if (lock_status_p == NULL) {`
		`+ /* if it was not initialized then allocates a structure`
		`+ * that will be private to that thread.`
		`+ * Later when the structure is retrieved (PR_GetThreadPrivate), the`
		`+ * content of the structure can be read/write without allocating`
		`+ * this private structure PR_SetThreadPrivate.`
		`+ * So this branch is processed one time per each thread`
		`+ */`
		`+ lock_status_p = (int *) slapi_ch_calloc(1, sizeof (int));`
		`+ PR_SetThreadPrivate(thread_plugin_lock_status, (void *) lock_status_p);`
		`+ *lock_status_p = MAP_RWLOCK_FREE;`
		`+ }`
		`+ ret = *lock_status_p;`
		`+ } else`
		`ret = (int) MAP_RWLOCK_UNINIT;`
		`#if DEBUG_MAP_LOCK`
		`slapi_log_error(SLAPI_LOG_FATAL, "get_plugin_monitor_status",`
		`- "lock_status = %d (%p)\n", ret, PR_GetCurrentThread());`
		`+ "(%s) lock_status = %d (%p)\n", use_lock_status ? "TRUE" : "FALSE", ret, (void *) PR_MyThreadId());`
		`#endif`
		`return ret;`
		`}`
		`@@ -2918,15 +2988,26 @@`
		`{`
		`#if DEBUG_MAP_LOCK`
		`slapi_log_error(SLAPI_LOG_FATAL, "set_plugin_monitor_status",`
		`- "lock_status = %d --> %d (%p)\n", get_plugin_monitor_status(), (int) lock_status, PR_GetCurrentThread());`
		`+ "(%s) lock_status = %d --> %d (%p)\n", use_lock_status ? "TRUE" : "FALSE", get_plugin_monitor_status(), (int) lock_status, (void *) PR_MyThreadId());`
		`#endif`

		`- if (thread_plugin_lock_status)`
		`- PR_SetThreadPrivate(thread_plugin_lock_status, (void *) lock_status);`
		`- else`
		`- PR_SetThreadPrivate(thread_plugin_lock_status, (void *) MAP_RWLOCK_UNINIT);`
		`-`
		`-`
		`+ if (use_lock_status) {`
		`+ int *lock_status_p;`
		`+`
		`+ lock_status_p = (int *) PR_GetThreadPrivate(thread_plugin_lock_status);`
		`+ if (lock_status_p == NULL) {`
		`+ /* if it was not initialized then allocates a structure`
		`+ * that will be private to that thread.`
		`+ * Later when the structure is retrieved (PR_GetThreadPrivate), the`
		`+ * content of the structure can be read/write without allocating`
		`+ * this private structure PR_SetThreadPrivate.`
		`+ * So this branch is processed one time per each thread`
		`+ */`
		`+ lock_status_p = (int *) slapi_ch_calloc(1, sizeof (int));`
		`+ PR_SetThreadPrivate(thread_plugin_lock_status, (void *) lock_status_p);`
		`+ }`
		`+ *lock_status_p = lock_status;`
		`+ }`
		`}`

		`int`
		`@@ -2934,13 +3015,27 @@`
		`{`
		`int ret;`

		`- if (thread_plugin_lock_count)`
		`- ret = (int) PR_GetThreadPrivate(thread_plugin_lock_count);`
		`- else`
		`+ if (use_lock_count) {`
		`+ int *lock_count;`
		`+ lock_count = (int *) PR_GetThreadPrivate(thread_plugin_lock_count);`
		`+ if (lock_count == NULL) {`
		`+ /* if it was not initialized then allocates a structure`
		`+ * that will be private to that thread.`
		`+ * Later when the structure is retrieved (PR_GetThreadPrivate), the`
		`+ * content of the structure can be read/write without allocating`
		`+ * this private structure PR_SetThreadPrivate.`
		`+ * So this branch is processed one time per each thread`
		`+ */`
		`+ lock_count = (int *) slapi_ch_calloc(1, sizeof (int));`
		`+ PR_SetThreadPrivate(thread_plugin_lock_count, (void *) lock_count);`
		`+ *lock_count = 0;`
		`+ }`
		`+ ret = *lock_count;`
		`+ } else`
		`ret = (int) MAP_RWLOCK_UNINIT;`
		`#if DEBUG_MAP_LOCK`
		`slapi_log_error(SLAPI_LOG_FATAL, "get_plugin_monitor_count",`
		`- "lock_count = %d (%p)\n", ret, PR_GetCurrentThread());`
		`+ "(%s) lock_count = %d (%p)\n", use_lock_count ? "TRUE" : "FALSE", ret, (void *) PR_MyThreadId());`
		`#endif`
		`return ret;`
		`}`
		`@@ -2950,13 +3045,23 @@`
		`{`
		`#if DEBUG_MAP_LOCK`
		`slapi_log_error(SLAPI_LOG_FATAL, "set_plugin_monitor_count",`
		`- "lock_count = %d --> %d (%p)\n", get_plugin_monitor_count(), (int) lock_count, PR_GetCurrentThread());`
		`+ "(%s) lock_count = %d --> %d (%p)\n", use_lock_count ? "TRUE" : "FALSE", get_plugin_monitor_count(), (int) lock_count, (void *) PR_MyThreadId());`
		`#endif`
		`-`
		`- if (thread_plugin_lock_count)`
		`- PR_SetThreadPrivate(thread_plugin_lock_count, (void *) lock_count);`
		`- else`
		`- PR_SetThreadPrivate(thread_plugin_lock_count, (void *) MAP_RWLOCK_UNINIT);`
		`-`
		`-`
		`+ if (use_lock_count) {`
		`+ int *lock_count_p;`
		`+`
		`+ lock_count_p = (int *) PR_GetThreadPrivate(thread_plugin_lock_count);`
		`+ if (lock_count_p == NULL) {`
		`+ /* if it was not initialized then allocates a structure`
		`+ * that will be private to that thread.`
		`+ * Later when the structure is retrieved (PR_GetThreadPrivate), the`
		`+ * content of the structure can be read/write without allocating`
		`+ * this private structure PR_SetThreadPrivate.`
		`+ * So this branch is processed one time per each thread`
		`+ */`
		`+ lock_count_p = (int *) slapi_ch_calloc(1, sizeof (int));`
		`+ PR_SetThreadPrivate(thread_plugin_lock_count, (void *) lock_count_p);`
		`+ }`
		`+ *lock_count_p = lock_count;`
		`+ }`
		`}`

src/back-shr.h

file modified

		`@@ -30,12 +30,14 @@`
		`#define MAP_WLOCK_HELD 2`
		`#define MAP_RLOCK_HELD 1`
		`#define MAP_RWLOCK_FREE 0`
		`+ int PR_MyThreadId(void);`
		`int rw_monitor_enabled(void);`
		`int get_plugin_monitor_status(void);`
		`void set_plugin_monitor_status(int lock_status);`
		`int get_plugin_monitor_count(void);`
		`void set_plugin_monitor_count(int lock_count);`
		`void init_map_lock(void);`
		`+ Slapi_DN **ignored_containers_sdn;`


		`struct plugin_state;`

src/map.c

file modified

+125 -125

		`@@ -1248,7 +1248,7 @@`
		`map_rdlock(void)`
		`{`
		`int lock_status;`
		`- int lock_count;`
		`+ int lock_count;`
		`int rc = 0;`

		`if (rw_monitor_enabled() == MAP_MONITOR_DISABLED) {`
		`@@ -1260,63 +1260,63 @@`


		`lock_status = get_plugin_monitor_status();`
		`- lock_count = get_plugin_monitor_count();`
		`+ lock_count = get_plugin_monitor_count();`

		`#if DEBUG_MAP_LOCK`
		`slapi_log_error(SLAPI_LOG_FATAL, "map_rdlock",`
		`- "thread_id = %p (call level = %d)\n", PR_GetCurrentThread(), wrap_get_call_level());`
		`+ "thread_id = %p (call level = %d)\n", (void *) PR_MyThreadId(), wrap_get_call_level());`
		`#endif`
		`if (lock_status == MAP_RWLOCK_UNINIT) {`
		`/* This is not initialized used the old way */`
		`slapi_log_error(SLAPI_LOG_FATAL, "schemacompat",`
		`"map rdlock: old way lock_status == MAP_RWLOCK_UNINIT\n");`
		`return wrap_rwlock_rdlock(map_data.lock);`
		`- }`
		`+ }`

		`- if (lock_status == MAP_RWLOCK_FREE) {`
		`- /* The plugin lock is free, acquire it */`
		`+ if (lock_status == MAP_RWLOCK_FREE) {`
		`+ /* The plugin lock is free, acquire it */`
		`#if DEBUG_MAP_LOCK`
		`- slapi_log_error(SLAPI_LOG_FATAL, "schemacompat",`
		`- "map rdlock: current lock_status == MAP_RWLOCK_FREE\n");`
		`+ slapi_log_error(SLAPI_LOG_FATAL, "schemacompat",`
		`+ "map rdlock: current lock_status == MAP_RWLOCK_FREE\n");`
		`#endif`
		`- set_plugin_monitor_status(MAP_RLOCK_HELD);`
		`- set_plugin_monitor_count(1);`
		`+ set_plugin_monitor_status(MAP_RLOCK_HELD);`
		`+ set_plugin_monitor_count(1);`
		`#if DEBUG_MAP_LOCK`
		`- if (lock_count != 0) {`
		`- slapi_log_error(SLAPI_LOG_FATAL, "schemacompat",`
		`- "map rdlock: (%p) ALERT !!! count was %d -> 1\n", PR_GetCurrentThread(), lock_count);`
		`- }`
		`+ if (lock_count != 0) {`
		`+ slapi_log_error(SLAPI_LOG_FATAL, "schemacompat",`
		`+ "map rdlock: (%p) ALERT !!! count was %d -> 1\n", (void *) PR_MyThreadId(), lock_count);`
		`+ }`
		`#endif`

		`- /* Acquire the slapi plugin in read */`
		`- rc = plugin_rdlock();`
		`- if (rc) {`
		`- slapi_log_error(SLAPI_LOG_FATAL, "schemacompat",`
		`- "map rdlock: (%p) MAP_RWLOCK_FREE -> MAP_RLOCK_HELD: fail to read lock plugin lock (%d)\n", PR_GetCurrentThread(), rc);`
		`- return rc;`
		`- }`
		`+ /* Acquire the slapi plugin in read */`
		`+ rc = plugin_rdlock();`
		`+ if (rc) {`
		`+ slapi_log_error(SLAPI_LOG_FATAL, "schemacompat",`
		`+ "map rdlock: (%p) MAP_RWLOCK_FREE -> MAP_RLOCK_HELD: fail to read lock plugin lock (%d)\n", (void *) PR_MyThreadId(), rc);`
		`+ return rc;`
		`+ }`
		`#if DEBUG_MAP_LOCK`
		`- slapi_log_error(SLAPI_LOG_FATAL, "schemacompat",`
		`- "map rdlock: (%p) MAP_RWLOCK_FREE -> MAP_RLOCK_HELD : count=%d\n", PR_GetCurrentThread(), 1);`
		`+ slapi_log_error(SLAPI_LOG_FATAL, "schemacompat",`
		`+ "map rdlock: (%p) MAP_RWLOCK_FREE -> MAP_RLOCK_HELD : count=%d\n", (void *) PR_MyThreadId(), 1);`
		`#endif`
		`- rc = wrap_rwlock_rdlock(map_data.lock);`
		`- if (rc) {`
		`- slapi_log_error(SLAPI_LOG_FATAL, "schemacompat",`
		`- "Fail to acquire map lock in read (%d)\n", rc);`
		`- plugin_unlock();`
		`- return rc;`
		`- }`
		`- return 0;`
		`- }`
		`+ rc = wrap_rwlock_rdlock(map_data.lock);`
		`+ if (rc) {`
		`+ slapi_log_error(SLAPI_LOG_FATAL, "schemacompat",`
		`+ "Fail to acquire map lock in read (%d)\n", rc);`
		`+ plugin_unlock();`
		`+ return rc;`
		`+ }`
		`+ return 0;`
		`+ }`

		`#if DEBUG_MAP_LOCK`
		`- slapi_log_error(SLAPI_LOG_FATAL, "schemacompat",`
		`- "map rdlock: (%p) was already hold %s : count=%d > %d!!!\n",`
		`- PR_GetCurrentThread(),`
		`- (lock_status == MAP_WLOCK_HELD) ? "MAP_WLOCK_HELD": "MAP_RLOCK_HELD",`
		`- lock_count, lock_count + 1);`
		`+ slapi_log_error(SLAPI_LOG_FATAL, "schemacompat",`
		`+ "map rdlock: (%p) was already hold %s : count=%d > %d!!!\n",`
		`+ (void *) PR_MyThreadId(),`
		`+ (lock_status == MAP_WLOCK_HELD) ? "MAP_WLOCK_HELD" : "MAP_RLOCK_HELD",`
		`+ lock_count, lock_count + 1);`
		`#endif`
		`- set_plugin_monitor_count(lock_count + 1);`
		`+ set_plugin_monitor_count(lock_count + 1);`
		`return 0;`
		`}`

		`@@ -1324,7 +1324,7 @@`
		`map_wrlock(void)`
		`{`
		`int lock_status;`
		`- int lock_count;`
		`+ int lock_count;`
		`int rc = 0;`

		`if (rw_monitor_enabled() == MAP_MONITOR_DISABLED) {`
		`@@ -1335,11 +1335,11 @@`
		`}`

		`lock_status = get_plugin_monitor_status();`
		`- lock_count = get_plugin_monitor_count();`
		`+ lock_count = get_plugin_monitor_count();`

		`#if DEBUG_MAP_LOCK`
		`slapi_log_error(SLAPI_LOG_FATAL, "map wrlock",`
		`- "thread_id = %p (call level = %d)\n", PR_GetCurrentThread(), wrap_get_call_level());`
		`+ "thread_id = %p (call level = %d)\n", (void *) PR_MyThreadId(), wrap_get_call_level());`
		`#endif`
		`if (lock_status == MAP_RWLOCK_UNINIT) {`
		`/* This is not initialized used the old way */`
		`@@ -1356,65 +1356,65 @@`
		`"map wrlock: current lock_status == MAP_LOCK_FREE\n");`
		`#endif`

		`- set_plugin_monitor_count(1);`
		`+ set_plugin_monitor_count(1);`
		`#if DEBUG_MAP_LOCK`
		`- if (lock_count != 0) {`
		`- slapi_log_error(SLAPI_LOG_FATAL, "schema-compat",`
		`- "map wrlock: (%p) ALERT !!! count was %d --> 1\n", PR_GetCurrentThread(), lock_count);`
		`- }`
		`+ if (lock_count != 0) {`
		`+ slapi_log_error(SLAPI_LOG_FATAL, "schema-compat",`
		`+ "map wrlock: (%p) ALERT !!! count was %d --> 1\n", (void *) PR_MyThreadId(), lock_count);`
		`+ }`
		`#endif`
		`- /* Acquire the slapi plugin in write */`
		`- rc = plugin_wrlock();`
		`- if (rc) {`
		`- slapi_log_error(SLAPI_LOG_FATAL, "schemacompat",`
		`- "map wrlock: (%p) MAP_RWLOCK_FREE -> MAP_RLOCK_HELD: fail to read lock plugin lock (%d)\n", PR_GetCurrentThread(), rc);`
		`- return rc;`
		`- }`
		`+ /* Acquire the slapi plugin in write */`
		`+ rc = plugin_wrlock();`
		`+ if (rc) {`
		`+ slapi_log_error(SLAPI_LOG_FATAL, "schemacompat",`
		`+ "map wrlock: (%p) MAP_RWLOCK_FREE -> MAP_RLOCK_HELD: fail to read lock plugin lock (%d)\n", (void *) PR_MyThreadId(), rc);`
		`+ return rc;`
		`+ }`
		`#if DEBUG_MAP_LOCK`
		`- slapi_log_error(SLAPI_LOG_FATAL, "schema-compat",`
		`- "map wrlock: (%p) MAP_RWLOCK_FREE --> MAP_WLOCK_HELD : count=%d\n", PR_GetCurrentThread(), 1);`
		`+ slapi_log_error(SLAPI_LOG_FATAL, "schema-compat",`
		`+ "map wrlock: (%p) MAP_RWLOCK_FREE --> MAP_WLOCK_HELD : count=%d\n", (void *) PR_MyThreadId(), 1);`
		`#endif`

		`- rc = wrap_rwlock_wrlock(map_data.lock);`
		`- if (rc) {`
		`- slapi_log_error(SLAPI_LOG_FATAL, "schema-compat",`
		`- "map wrlock: (%p) MAP_RWLOCK_FREE --> MAP_WLOCK_HELD : fail to write lock map lock (%d)\n", PR_GetCurrentThread(), rc);`
		`- plugin_unlock();`
		`- goto common;`
		`- }`
		`- } else {`
		`- set_plugin_monitor_count(lock_count + 1);`
		`+ rc = wrap_rwlock_wrlock(map_data.lock);`
		`+ if (rc) {`
		`+ slapi_log_error(SLAPI_LOG_FATAL, "schema-compat",`
		`+ "map wrlock: (%p) MAP_RWLOCK_FREE --> MAP_WLOCK_HELD : fail to write lock map lock (%d)\n", (void *) PR_MyThreadId(), rc);`
		`+ plugin_unlock();`
		`+ goto common;`
		`+ }`
		`+ } else {`
		`+ set_plugin_monitor_count(lock_count + 1);`
		`#if DEBUG_MAP_LOCK`
		`- slapi_log_error(SLAPI_LOG_FATAL, "schema-compat",`
		`- "map wrlock: (%p) %s --> MAP_WLOCK_HELD : count=%d\n",`
		`- PR_GetCurrentThread(),`
		`- (lock_status == MAP_WLOCK_HELD) ? "MAP_WLOCK_HELD": "MAP_RLOCK_HELD",`
		`- lock_count + 1);`
		`+ slapi_log_error(SLAPI_LOG_FATAL, "schema-compat",`
		`+ "map wrlock: (%p) %s --> MAP_WLOCK_HELD : count=%d\n",`
		`+ (void *) PR_MyThreadId(),`
		`+ (lock_status == MAP_WLOCK_HELD) ? "MAP_WLOCK_HELD" : "MAP_RLOCK_HELD",`
		`+ lock_count + 1);`
		`#endif`

		`- if (lock_status == MAP_RLOCK_HELD) {`
		`- /* lock is already acquired in read */`
		`+ if (lock_status == MAP_RLOCK_HELD) {`
		`+ /* lock is already acquired in read */`
		`#if DEBUG_MAP_LOCK`
		`- slapi_log_error(SLAPI_LOG_FATAL, "schema-compat",`
		`- "map wrlock: weird situation map lock is held in read and now required in write mode\n");`
		`+ slapi_log_error(SLAPI_LOG_FATAL, "schema-compat",`
		`+ "map wrlock: weird situation map lock is held in read and now required in write mode\n");`
		`#endif`
		`- /* First free the lock held in read */`
		`- rc = plugin_unlock();`
		`- if (rc) {`
		`- slapi_log_error(SLAPI_LOG_FATAL, "schema-compat",`
		`- "map wrlock: fail to unlock plugin lock (%d)\n", rc);`
		`- goto common;`
		`- }`
		`+ /* First free the lock held in read */`
		`+ rc = plugin_unlock();`
		`+ if (rc) {`
		`+ slapi_log_error(SLAPI_LOG_FATAL, "schema-compat",`
		`+ "map wrlock: fail to unlock plugin lock (%d)\n", rc);`
		`+ goto common;`
		`+ }`

		`- /* Second acquire it in write */`
		`- rc = plugin_wrlock();`
		`- if (rc) {`
		`- slapi_log_error(SLAPI_LOG_FATAL, "schema-compat",`
		`- "map wrlock: fail to write lock plugin lock (%d)\n", rc);`
		`- goto common;`
		`- }`
		`+ /* Second acquire it in write */`
		`+ rc = plugin_wrlock();`
		`+ if (rc) {`
		`+ slapi_log_error(SLAPI_LOG_FATAL, "schema-compat",`
		`+ "map wrlock: fail to write lock plugin lock (%d)\n", rc);`
		`+ goto common;`
		`}`
		`}`
		`+ }`

		`common:`
		`set_plugin_monitor_status(MAP_WLOCK_HELD);`
		`@@ -1425,7 +1425,7 @@`
		`map_unlock(void)`
		`{`
		`int lock_status;`
		`- int lock_count;`
		`+ int lock_count;`
		`int rc = 0;`

		`if (rw_monitor_enabled() == MAP_MONITOR_DISABLED) {`
		`@@ -1436,11 +1436,11 @@`
		`}`

		`lock_status = get_plugin_monitor_status();`
		`- lock_count = get_plugin_monitor_count();`
		`+ lock_count = get_plugin_monitor_count();`

		`#if DEBUG_MAP_LOCK`
		`slapi_log_error(SLAPI_LOG_FATAL, "map_unlock",`
		`- "thread_id = %p (call level = %d)\n", PR_GetCurrentThread(), wrap_get_call_level());`
		`+ "thread_id = %p (call level = %d)\n", (void *) PR_MyThreadId(), wrap_get_call_level());`
		`#endif`
		`if (lock_status == MAP_RWLOCK_UNINIT) {`
		`/* This is not initialized used the old way */`
		`@@ -1448,48 +1448,48 @@`
		`"map_unlock: old way lock_status == MAP_RWLOCK_UNINIT\n");`

		`return wrap_rwlock_unlock(map_data.lock);`
		`- }`
		`+ }`

		`- if (lock_count == 1) {`
		`- set_plugin_monitor_status(MAP_RWLOCK_FREE);`
		`- rc = plugin_unlock();`
		`- if (rc) {`
		`- slapi_log_error(SLAPI_LOG_FATAL, "schema-compat",`
		`- "map unlock: fail to unlock plugin lock (%d)\n", rc);`
		`- goto common;`
		`- }`
		`- #if DEBUG_MAP_LOCK`
		`+ if (lock_count == 1) {`
		`+ set_plugin_monitor_status(MAP_RWLOCK_FREE);`
		`+ rc = plugin_unlock();`
		`+ if (rc) {`
		`slapi_log_error(SLAPI_LOG_FATAL, "schema-compat",`
		`- "map_unlock: (%p) %s --> MAP_RWLOCK_FREE : count=%d\n",`
		`- PR_GetCurrentThread(),`
		`- (lock_status == MAP_WLOCK_HELD) ? "MAP_WLOCK_HELD" : (lock_status == MAP_RLOCK_HELD) ? "MAP_RLOCK_HELD" : "MAP_RWLOCK_FREE",`
		`- 0);`
		`+ "map unlock: fail to unlock plugin lock (%d)\n", rc);`
		`+ goto common;`
		`+ }`
		`+ #if DEBUG_MAP_LOCK`
		`+ slapi_log_error(SLAPI_LOG_FATAL, "schema-compat",`
		`+ "map_unlock: (%p) %s --> MAP_RWLOCK_FREE : count=%d\n",`
		`+ (void *) PR_MyThreadId(),`
		`+ (lock_status == MAP_WLOCK_HELD) ? "MAP_WLOCK_HELD" : (lock_status == MAP_RLOCK_HELD) ? "MAP_RLOCK_HELD" : "MAP_RWLOCK_FREE",`
		`+ 0);`
		`#endif`
		`- rc = wrap_rwlock_unlock(map_data.lock);`
		`- if (rc) {`
		`- slapi_log_error(SLAPI_LOG_FATAL, "schema-compat",`
		`+ rc = wrap_rwlock_unlock(map_data.lock);`
		`+ if (rc) {`
		`+ slapi_log_error(SLAPI_LOG_FATAL, "schema-compat",`
		`"map_unlock: fail to unlock map lock (%d)\n", rc);`
		`- goto common;`
		`- }`
		`+ goto common;`
		`}`
		`- if (lock_count >= 1) {`
		`- set_plugin_monitor_count(lock_count - 1);`
		`+ }`
		`+ if (lock_count >= 1) {`
		`+ set_plugin_monitor_count(lock_count - 1);`
		`#if DEBUG_MAP_LOCK`
		`- if (lock_count > 1) {`
		`- slapi_log_error(SLAPI_LOG_FATAL, "schema-compat",`
		`- "map_unlock: (%p) keep %s : count=%d\n",`
		`- PR_GetCurrentThread(),`
		`- (lock_status == MAP_WLOCK_HELD) ? "MAP_WLOCK_HELD" : (lock_status == MAP_RLOCK_HELD) ? "MAP_RLOCK_HELD" : "MAP_RWLOCK_FREE",`
		`- lock_count - 1);`
		`- } else {`
		`- slapi_log_error(SLAPI_LOG_FATAL, "schema-compat",`
		`- "map_unlock: (%p) is now %s : count=%d\n",`
		`- PR_GetCurrentThread(),`
		`- "MAP_RWLOCK_FREE",`
		`- lock_count - 1);`
		`- }`
		`- #endif`
		`+ if (lock_count > 1) {`
		`+ slapi_log_error(SLAPI_LOG_FATAL, "schema-compat",`
		`+ "map_unlock: (%p) keep %s : count=%d\n",`
		`+ (void *) PR_MyThreadId(),`
		`+ (lock_status == MAP_WLOCK_HELD) ? "MAP_WLOCK_HELD" : (lock_status == MAP_RLOCK_HELD) ? "MAP_RLOCK_HELD" : "MAP_RWLOCK_FREE",`
		`+ lock_count - 1);`
		`+ } else {`
		`+ slapi_log_error(SLAPI_LOG_FATAL, "schema-compat",`
		`+ "map_unlock: (%p) is now %s : count=%d\n",`
		`+ (void *) PR_MyThreadId(),`
		`+ "MAP_RWLOCK_FREE",`
		`+ lock_count - 1);`
		`}`
		`+ #endif`
		`+ }`

		`common:`
		`return rc;`

src/plug-sch.c

file modified

		`@@ -197,6 +197,13 @@`
		`if (state->plugin_base != NULL) {`
		`slapi_ch_free((void **)&state->plugin_base);`
		`}`
		`+ if (ignored_containers_sdn) {`
		`+ int i;`
		`+ for (i = 0; ignored_containers_sdn[i]; i++) {`
		`+ slapi_sdn_free(&ignored_containers_sdn[i]);`
		`+ }`
		`+ slapi_ch_free((void **)&ignored_containers_sdn);`
		`+ }`
		`slapi_log_error(SLAPI_LOG_PLUGIN, state->plugin_desc->spd_id,`
		`"plugin shutdown completed\n");`
		`return 0;`

tbordaz commented 5 years ago

This patch is composed of 3 patches:

        Fix of threa private initialization
        The initialization of the thread private variable was buggy.
        The private variable required an allocated struct (per thread).
        The struct is allocated on demand (during get/set) when the
        retrieved (PR_GetThreadPrivate) struct is NULL.

        Improve debug messages
        A pstack is showing threadId that differs from the
        the thread pointer. To match logs with pstack
        better to display the threadId

        Ignores updates under cn=config/cn=schema
       The true cause of the hang was that some updates on 'cn=config'
        can skip the BEPOST phase. (in this bug it was the maxbersize setting).
        The consequence is that the slapi-nis map lock was acquired but not released.
        The fix consist to ignore (not lock slapi-nis map) write operation done
        on 'cn=config' and 'cn=schema'

rebased onto d7565666c62ad2a9c8ac4992fff57b8ce65d7cbe

5 years ago