Summary:	ASTERISK-11625: Deadlock/Locked channels
Reporter:	Joel Vandal (jvandal)	Labels:
Date Opened:	2008-03-12 10:43:59	Date Closed:	2008-03-13 14:31:50
Priority:	Blocker	Regression?	No
Status:	Closed/Complete	Components:	Channels/General
Versions:		Frequency of Occurrence
Related Issues:
Environment:		Attachments:	( 0) backtrace.txt ( 1) bt.txt ( 2) bt2.txt ( 3) lock.txt
Description:	I'm testing patch from ticket 12098 and now we get some deadlock when I try to do 'soft hangup <tab>, I must restart CLI in order to execute others commands.
Comments:	By: Tilghman Lesher (tilghman) 2008-03-12 13:26:35 There is no actual error in that output.  We're going to need you to attach to the process with gdb and do a 'thread apply all bt' and 'thread apply all bt full' to see what it's hanging on. By: Joel Vandal (jvandal) 2008-03-12 15:05:49 bt2.txt is in fact 'core show locks' By: Joel Vandal (jvandal) 2008-03-12 15:20:29 I just try to do : soft hangup Local/1344@default-agent-52bf,2 and got this 2 minutes later (strange... this is a SIP channel and talk about IAX.. can be unrelated): [Mar 12 16:21:57] DEBUG[30902]: chan_iax2.c:1909 iax2_destroy_helper: Unable to cancel schedule ID 1114.  This is probably a bug (chan_iax2.c: iax2_destroy_helper, line 1909). Channel doesnt want to hangup. > show channels concise Local/1344@default-agent-52bf,2!default-local-devices!1344!2!Ring!Dial!SIP/1344||t!7094697962!!3!1314!(None) Local/1271@default-agent-e39f,2!default-local-devices!1271!2!Ring!Dial!SIP/1271||t!7094697962!!3!1314!(None) Local/1273@default-agent-3082,2!default-local-devices!1273!2!Ring!Dial!SIP/1273||t!7094697962!!3!1314!(None) By: Joel Vandal (jvandal) 2008-03-12 15:46:07 If I turn on debug on my server, I'm flooded by this error messages, this can be a loop ? 3 x processid (6000, 6001, 30974) and 3 x locked channels. [Mar 12 16:44:43] DEBUG[6000]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry -1! [Mar 12 16:44:43] DEBUG[6001]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry -1! [Mar 12 16:44:43] DEBUG[30974]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry -1! [Mar 12 16:44:43] DEBUG[6000]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry -1! [Mar 12 16:44:43] DEBUG[6001]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry -1! [Mar 12 16:44:43] DEBUG[30974]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry -1! [Mar 12 16:44:43] DEBUG[6000]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry -1! [Mar 12 16:44:43] DEBUG[6001]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry -1! [Mar 12 16:44:43] DEBUG[30974]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry -1! By: Joel Vandal (jvandal) 2008-03-12 21:08:24 I've also test branches/1.6.0 to see if I can see same problems on 1.6 and yes :( I see no error/lock on 'core show locks' but have lots of "zombie/orphan" channels. Here some log captured from CLI (1.6) Mar 12 22:02:15] DEBUG[5508]: sched.c:291 ast_sched_del: Attempted to delete nonexistent schedule entry -1! [Mar 12 22:02:20] DEBUG[5508]: chan_sip.c:18389 do_monitor: chan_sip: ast_sched_runq ran 36 all at once [Mar 12 22:02:25] DEBUG[5508]: chan_sip.c:18389 do_monitor: chan_sip: ast_sched_runq ran 26 all at once [Mar 12 22:02:25] DEBUG[5508]: chan_sip.c:18389 do_monitor: chan_sip: ast_sched_runq ran 26 all at once [Mar 12 22:02:30] DEBUG[5508]: chan_sip.c:18389 do_monitor: chan_sip: ast_sched_runq ran 21 all at once [Mar 12 22:02:30] DEBUG[5508]: chan_sip.c:18389 do_monitor: chan_sip: ast_sched_runq ran 31 all at once [Mar 12 22:02:35] DEBUG[5508]: chan_sip.c:18389 do_monitor: chan_sip: ast_sched_runq ran 26 all at once [Mar 12 22:02:45] DEBUG[5508]: audiohook.c:223 audiohook_read_frame_both: Failed to get 160 samples from read factory 0x9aedff0 [Mar 12 22:02:45] DEBUG[5508]: audiohook.c:223 audiohook_read_frame_both: Failed to get 160 samples from read factory 0x9af5778 [Mar 12 22:02:45] DEBUG[5508]: audiohook.c:223 audiohook_read_frame_both: Failed to get 160 samples from read factory 0x9af9a38 [Mar 12 22:02:45] DEBUG[5508]: audiohook.c:223 audiohook_read_frame_both: Failed to get 160 samples from read factory 0xb14acd8 [Mar 12 22:02:45] DEBUG[5508]: audiohook.c:223 audiohook_read_frame_both: Failed to get 160 samples from read factory 0x9b06ad8 [Mar 12 22:02:45] DEBUG[5508]: audiohook.c:223 audiohook_read_frame_both: Failed to get 160 samples from read factory 0x9b0fa08 [Mar 12 22:02:45] DEBUG[5508]: audiohook.c:223 audiohook_read_frame_both: Failed to get 160 samples from read factory 0x9b17ad8 [Mar 12 22:02:45] DEBUG[5508]: audiohook.c:223 audiohook_read_frame_both: Failed to get 160 samples from read factory 0x9b495b0 [Mar 12 22:02:45] DEBUG[5508]: audiohook.c:223 audiohook_read_frame_both: Failed to get 160 samples from read factory 0x9678470 [Mar 12 22:02:45] DEBUG[5508]: audiohook.c:223 audiohook_read_frame_both: Failed to get 160 samples from read factory 0x9667600 [Mar 12 22:02:45] DEBUG[5508]: audiohook.c:223 audiohook_read_frame_both: Failed to get 160 samples from read factory 0xb7447f8 [Mar 12 22:02:45] DEBUG[5508]: audiohook.c:223 audiohook_read_frame_both: Failed to get 160 samples from read factory 0x9b1b768 [Mar 12 22:02:45] DEBUG[5508]: audiohook.c:223 audiohook_read_frame_both: Failed to get 160 samples from read factory 0xb30ac88 [Mar 12 22:02:45] DEBUG[5508]: audiohook.c:223 audiohook_read_frame_both: Failed to get 160 samples from read factory 0x9b1ef68 [Mar 12 22:02:45] DEBUG[5508]: audiohook.c:223 audiohook_read_frame_both: Failed to get 160 samples from read factory 0x9a23518 [Mar 12 22:02:45] DEBUG[5508]: audiohook.c:223 audiohook_read_frame_both: Failed to get 160 samples from read factory 0x9b225d0 [Mar 12 22:02:45] DEBUG[5508]: audiohook.c:223 audiohook_read_frame_both: Failed to get 160 samples from read factory 0xb3efc58 [Mar 12 22:02:45] DEBUG[5508]: audiohook.c:223 audiohook_read_frame_both: Failed to get 160 samples from read factory 0x983b630 [Mar 12 22:02:45] DEBUG[5508]: audiohook.c:223 audiohook_read_frame_both: Failed to get 160 samples from read factory 0x995d130 [Mar 12 22:02:45] DEBUG[5508]: audiohook.c:223 audiohook_read_frame_both: Failed to get 160 samples from read factory 0xb84cc20 [Mar 12 22:02:45] DEBUG[5508]: chan_sip.c:18389 do_monitor: chan_sip: ast_sched_runq ran 52 all at once [Mar 12 22:02:45] DEBUG[5508]: audiohook.c:223 audiohook_read_frame_both: Failed to get 160 samples from read factory 0xb7ae2a8 [Mar 12 22:02:45] DEBUG[5508]: audiohook.c:223 audiohook_read_frame_both: Failed to get 160 samples from read factory 0xb7bed30 [Mar 12 22:02:45] DEBUG[5508]: audiohook.c:223 audiohook_read_frame_both: Failed to get 160 samples from read factory 0x97112b0 [Mar 12 22:02:45] DEBUG[5508]: audiohook.c:223 audiohook_read_frame_both: Failed to get 160 samples from read factory 0x9aea060 [Mar 12 22:02:45] DEBUG[5508]: audiohook.c:223 audiohook_read_frame_both: Failed to get 160 samples from read factory 0x99bc200 [Mar 12 22:02:45] DEBUG[5508]: audiohook.c:223 audiohook_read_frame_both: Failed to get 160 samples from read factory 0x9b78228 By: Mark Michelson (mmichelson) 2008-03-13 14:31:48 The patch from issue ASTERISK-11537 IS causing this to happen. As such, I'm closing this issue and moving the discussion back to 12098.