Re: mISDN_send: error -12 strikes again

Yet another Scenario of a deadlock:

thread               name       lock       file        function              line
0xb6157b70           c          0x975a640  astobj2.c   internal_ao2_callback  657
0xb6157b70           chan       0xfd1e9f8  channel.c   ast_channel_cmp_cb    1691

Waiting for:                               channel.c   ast_indicate_data     4323


0xb4beeb70           chan       0xfd1e9f8  channel.c   ast_indicate_data     4323
0xb4beeb70           &chan_lock 0xb5c55a80 chan_lcr.c  lcr_indicate          2920

Waiting for:                               chan_lcr.c  lock_chan             2012

Information for chan_lcr.c  lock_chan is missing.

but it is this one:

Thread 19 (Thread 0xb56bfb70 (LWP 2343)):
#0  0xb7814424 in __kernel_vsyscall ()
#1  0xb7526c89 in __lll_lock_wait () from /lib/i686/cmov/libpthread.so.0
#2  0xb7522099 in _L_lock_839 () from /lib/i686/cmov/libpthread.so.0
#3  0xb7521f2b in pthread_mutex_lock () from /lib/i686/cmov/libpthread.so.0
#4  0x08113001 in __ast_pthread_mutex_lock (filename=0x81b8fbc "astobj2.c", 
    lineno=493, func=0x81b91bd "internal_ao2_link", mutex_name=0x81b90b8 "c", 
    t=0x975a640) at lock.c:244
#5  0x080851f8 in __ao2_lock (user_data=0x975a670, file=0x81b8fbc "astobj2.c", 
    func=0x81b91bd "internal_ao2_link", line=493, var=0x81b90b8 "c")
    at astobj2.c:157
#6  0x080858f9 in internal_ao2_link (c=0x975a670, user_data=0xfd85498, 
    file=0x81b8fbc "astobj2.c", line=517, func=0x81b91a1 "__ao2_link")
    at astobj2.c:493
#7  0x08085a7a in __ao2_link (c=0x975a670, user_data=0xfd85498)
    at astobj2.c:517
#8  0x080a803f in __ast_channel_alloc_ap (needqueue=1, state=1, cid_num=0x0, 
    cid_name=0x0, acctcode=0xb5c5152b "", exten=0x0, context=0xb5c5152b "", 
    linkedid=0xb5c5152b "", amaflag=0, file=0xb5c5121f "chan_lcr.c", line=924, 
    function=0xb5c53dde "lcr_in_setup", name_fmt=0xb5c514f3 "%s/%d", 
    ap1=0xb56a63f4 "\fT\305\265\020\001", ap2=0xb56a63f4 "\fT\305\265\020\001")
    at channel.c:1312
#9  0x080a82a8 in __ast_channel_alloc (needqueue=1, state=1, cid_num=0x0, 
    cid_name=0x0, acctcode=0xb5c5152b "", exten=0x0, context=0xb5c5152b "", 
    linkedid=0xb5c5152b "", amaflag=0, file=0xb5c5121f "chan_lcr.c", line=924, 
    function=0xb5c53dde "lcr_in_setup", name_fmt=0xb5c514f3 "%s/%d")
    at channel.c:1357
#10 0xb5c4c93e in lcr_in_setup (fd=0xb5c55a60, what=<value optimized out>, 
    instance=0x0, index=0) at chan_lcr.c:924
#11 receive_message (fd=0xb5c55a60, what=<value optimized out>, instance=0x0, 
    index=0) at chan_lcr.c:1666
#12 handle_socket (fd=0xb5c55a60, what=<value optimized out>, instance=0x0, 
    index=0) at chan_lcr.c:1801
#13 0xb5c50d5c in select_main (polling=0, global_change=0xb5c558c8, 
    lock=0xb5c45a80 <lock_chan>, unlock=0xb5c45ad0 <unlock_chan>)
    at select.c:168

Offending call: ast_channel_alloc

I've tried to patch this as attached but when running my stress-test,
asterisk gets into a state where it no longer accepts calls (lcradmin
state doesn't show *any* call activity) -- silently, the call just
hangs. But we don't get any deadlocks anymore. Looks like somehow data
structures get inconsistent somewhere.

I've also tried to *always* lock in lcr_hangup (not conditionally by
thread id, I think this is a bad idea) but this doesn't change anything,
the change is also in the patch below.

But this is still the version where hfcmulti isn't working (one-way
audio, see separate emails), so this might be related to the hfcmulti
bug, I will have to test this on an older version of the mISDN stack to
confirm.

The "good" news is that I'm down to below a minute when trying to
reproduce this by running 4 processes that start calls and one process
that tears down calls simulateneously. With this setup I'm able to
reliably get the deadlock in under a minute. The state described above
where Asterisk no longer accepts calls is reached after several minutes.

Patch, do not apply, just for illustration:

diff --git a/chan_lcr.c b/chan_lcr.c
index df5b4fc..2fc705e 100644
--- a/chan_lcr.c
+++ b/chan_lcr.c
@@ -913,7 +913,10 @@ static void lcr_in_setup(struct chan_call *call, int message_type, union paramet
 
 	CDEBUG(call, NULL, "Incomming setup from LCR. (callerid %s, dialing %s)\n", param->setup.callerinfo.id, param->setup.dialinginfo.id);
 
-	/* create asterisk channel instrance */
+        /* Unlock before calling into asterisk! */
+        ast_mutex_unlock(&chan_lock);
+        
+	/* create asterisk channel instance */
 
 	#ifdef LCR_FOR_CALLWEAVER
 	ast = ast_channel_alloc(1);
@@ -927,6 +930,9 @@ static void lcr_in_setup(struct chan_call *call, int message_type, union paramet
 #endif
 	#endif
 
+        /* Re-lock after calling into asterisk! */
+        ast_mutex_lock(&chan_lock);
+
 	if (!ast) {
 		/* release */
 		CERROR(call, NULL, "Failed to create Asterisk channel - releasing.\n");
@@ -1498,7 +1504,7 @@ void lcr_in_dtmf(struct chan_call *call, int val)
 /*
  * message received from LCR
  */
-int receive_message(int message_type, unsigned int ref, union parameter *param)
+static int receive_message(int message_type, unsigned int ref, union parameter *param)
 {
 	struct bchannel *bchannel;
 	struct chan_call *call;
@@ -2082,7 +2088,10 @@ struct ast_channel *lcr_request(const char *type, int format, void *data, int *c
 		return NULL;
 	}
 
-	/* create asterisk channel instrance */
+        /* Unlock before calling into asterisk! */
+        ast_mutex_unlock(&chan_lock);
+        
+	/* create asterisk channel instance */
 
 	#ifdef LCR_FOR_ASTERISK
 #ifdef AST_1_8_OR_HIGHER
@@ -2096,6 +2105,9 @@ struct ast_channel *lcr_request(const char *type, int format, void *data, int *c
 	ast = ast_channel_alloc(1);
 	#endif
 
+        /* Re-lock after calling into asterisk! */
+        ast_mutex_lock(&chan_lock);
+
 	if (!ast) {
 		CERROR(NULL, NULL, "Failed to create Asterisk channel.\n");
 		free_call(call);
@@ -2678,9 +2690,7 @@ static int lcr_hangup(struct ast_channel *ast)
 	struct chan_call *call;
 	pthread_t tid = pthread_self();
 
-	if (!pthread_equal(tid, chan_tid)) {
-		ast_mutex_lock(&chan_lock);
-	}
+	ast_mutex_lock(&chan_lock);
 #if ASTERISK_VERSION_NUM < 110000
 	call = ast->tech_pvt;
 #else
@@ -2688,9 +2698,7 @@ static int lcr_hangup(struct ast_channel *ast)
 #endif
 	if (!call) {
 		CERROR(NULL, ast, "Received hangup from Asterisk, but no call instance exists.\n");
-		if (!pthread_equal(tid, chan_tid)) {
-			ast_mutex_unlock(&chan_lock);
-		}
+		ast_mutex_unlock(&chan_lock);
 		return -1;
 	}
 
@@ -2720,9 +2728,7 @@ static int lcr_hangup(struct ast_channel *ast)
 			send_release_and_import(call, CAUSE_NORMAL, LOCATION_PRIVATE_LOCAL);
 		/* remove call */
 		free_call(call);
-		if (!pthread_equal(tid, chan_tid)) {
-			ast_mutex_unlock(&chan_lock);
-		}
+		ast_mutex_unlock(&chan_lock);
 		return 0;
 	} else {
 		/* ref is not set, due to prepare setup or release */
@@ -2737,9 +2743,7 @@ static int lcr_hangup(struct ast_channel *ast)
 			call->ast = NULL;
 		}
 	}
-	if (!pthread_equal(tid, chan_tid)) {
-		ast_mutex_unlock(&chan_lock);
-	}
+	ast_mutex_unlock(&chan_lock);
 	return 0;
 }
 

-- 
Ralf Schlatterbeck             email: [email protected]