ASTERISK-11517: when calling chanspy(,q) deadlocks occurs

[Home]

Summary: ASTERISK-11517: when calling chanspy(,q) deadlocks occurs

Reporter: Clod Patry (junky) Labels:

Date Opened: 2008-02-26 14:46:02.000-0600 Date Closed: 2008-02-27 11:34:07.000-0600

Priority: Minor Regression? No

Status: Closed/Complete Components: Applications/app_chanspy

Versions: Frequency of
Occurrence

Related
Issues:

Environment: Attachments:

Description: after ive an IAX2 channel calling a sip channel, the call goes well.

if im calling chanspy, deadlocks occurs:

-- Executing [601@aheeva:1] ChanSpy("SIP/5556-097dfe78", "|q") in new stack
localhost*CLI> core show locks
localhost*CLI>
=======================================================================
=== Currently Held Locks ==============================================
=======================================================================
===
=== <file> <line num> <function> <lock name> <lock addr> (times locked)
===
=== Thread ID: 3086330784 (listener started at [ 1063] asterisk.c ast_makesocket())
=== -------------------------------------------------------------------
===
=== Thread ID: 3086072736 (do_devstate_changes started at [ 386] devicestate.c ast_device_state_engine_init())
=== -------------------------------------------------------------------
===
=== Thread ID: 3085826976 (do_parking_thread started at [ 2456] res_features.c load_module())
=== -------------------------------------------------------------------
===
=== Thread ID: 3085581216 (ctiServerReceiver started at [ 4161] app_ahEventsProxy.c load_module())
=== -------------------------------------------------------------------
===
=== Thread ID: 2560842656 (do_monitor started at [ 6988] chan_zap.c restart_monitor())
=== -------------------------------------------------------------------
===
=== Thread ID: 2560596896 (scan_thread started at [ 499] pbx_spool.c load_module())
=== -------------------------------------------------------------------
===
=== Thread ID: 2560351136 (sla_thread started at [ 4844] app_meetme.c sla_load_config())
=== -------------------------------------------------------------------
===
=== Thread ID: 2560105376 (do_monitor started at [15701] chan_sip.c restart_monitor())
=== -------------------------------------------------------------------
===
=== Thread ID: 2559859616 (wrapupchecker_thread started at [ 7439] app_AheevaPhoneSimulator.c load_module())
=== -------------------------------------------------------------------
===
=== Thread ID: 2559613856 (recording_sender_thread started at [ 7441] app_AheevaPhoneSimulator.c load_module())
=== -------------------------------------------------------------------
===
=== Thread ID: 2559368096 (communication_server_thread started at [ 7470] app_AheevaPhoneSimulator.c load_module())
=== -------------------------------------------------------------------
===
=== Thread ID: 2559122336 (iax2_process_thread started at [ 8883] chan_iax2.c start_network_thread())
=== -------------------------------------------------------------------
===
=== Thread ID: 2558876576 (iax2_process_thread started at [ 8883] chan_iax2.c start_network_thread())
=== -------------------------------------------------------------------
===
=== Thread ID: 2558630816 (iax2_process_thread started at [ 8883] chan_iax2.c start_network_thread())
=== -------------------------------------------------------------------
===
=== Thread ID: 2558385056 (iax2_process_thread started at [ 8883] chan_iax2.c start_network_thread())
=== -------------------------------------------------------------------
===
=== Thread ID: 2558139296 (iax2_process_thread started at [ 8883] chan_iax2.c start_network_thread())
=== -------------------------------------------------------------------
===
=== Thread ID: 2557893536 (iax2_process_thread started at [ 8883] chan_iax2.c start_network_thread())
=== -------------------------------------------------------------------
===
=== Thread ID: 2557647776 (iax2_process_thread started at [ 8883] chan_iax2.c start_network_thread())
=== -------------------------------------------------------------------
===
=== Thread ID: 2557402016 (iax2_process_thread started at [ 8883] chan_iax2.c start_network_thread())
=== -------------------------------------------------------------------
===
=== Thread ID: 2557156256 (iax2_process_thread started at [ 8883] chan_iax2.c start_network_thread())
=== -------------------------------------------------------------------
===
=== Thread ID: 2556910496 (iax2_process_thread started at [ 8883] chan_iax2.c start_network_thread())
=== -------------------------------------------------------------------
===
=== Thread ID: 2556664736 (sched_thread started at [ 8893] chan_iax2.c start_network_thread())
=== -------------------------------------------------------------------
===
=== Thread ID: 2556418976 (network_thread started at [ 8894] chan_iax2.c start_network_thread())
=== -------------------------------------------------------------------
===
=== Thread ID: 2556132256 (monitor_sig_flags started at [ 3001] asterisk.c main())
=== -------------------------------------------------------------------
===
=== Thread ID: 2555886496 (netconsole started at [ 1005] asterisk.c listener())
=== -------------------------------------------------------------------
===
=== Thread ID: 2555640736 (pbx_thread started at [ 2647] pbx.c ast_pbx_start())
=== ---> Lock #0 (chan_agent.c): MUTEX 2181 __login_exec &p->app_lock 0x979c060 (1)
=== -------------------------------------------------------------------
===
=== Thread ID: 2555390880 (pbx_thread started at [ 2647] pbx.c ast_pbx_start())
=== -------------------------------------------------------------------
===
=== Thread ID: 2555145120 (autoservice_run started at [ 194] autoservice.c ast_autoservice_start())
=== -------------------------------------------------------------------
===
=== Thread ID: 2554895264 (pbx_thread started at [ 2647] pbx.c ast_pbx_start())
=== ---> Lock #0 (app_chanspy.c): MUTEX 401 chanspy_ds_free &chanspy_ds->lock 0x98484854 (1)
=== ---> Waiting for Lock #1 (app_chanspy.c): MUTEX 408 chanspy_ds_free &chan->lock 0x97dd490 (1)
=== -------------------------------------------------------------------
===
=======================================================================

And when the chanspy and the call ends:
eb 26 15:43:46] ERROR[23473]: /usr/src/asterisk-1.4/include/asterisk/lock.h:370 __ast_pthread_mutex_lock: app_chanspy.c line 408 (chanspy_ds_free): '&chan->lock' really deep reentrancy!
[Feb 26 15:43:46] ERROR[23473]: /usr/src/asterisk-1.4/include/asterisk/lock.h:370 __ast_pthread_mutex_lock: app_chanspy.c line 408 (chanspy_ds_free): '&chan->lock' really deep reentrancy!
[Feb 26 15:43:46] ERROR[23473]: /usr/src/asterisk-1.4/include/asterisk/lock.h:370 __ast_pthread_mutex_lock: app_chanspy.c line 408 (chanspy_ds_free): '&chan->lock' really deep reentrancy!
[Feb 26 15:43:46] ERROR[23473]: /usr/src/asterisk-1.4/include/asterisk/lock.h:370 __ast_pthread_mutex_lock: app_chanspy.c line 408 (chanspy_ds_free): '&chan->lock' really deep reentrancy!
[Feb 26 15:43:46] ERROR[23473]: /usr/src/asterisk-1.4/include/asterisk/lock.h:370 __ast_pthread_mutex_lock: app_chanspy.c line 408 (chanspy_ds_free): '&chan->lock' really deep reentrancy!
[Feb 26 15:43:46] ERROR[23473]: /usr/src/asterisk-1.4/include/asterisk/lock.h:370 __ast_pthread_mutex_lock: app_chanspy.c line 408 (chanspy_ds_free): '&chan->lock' really deep reentrancy!
[Feb 26 15:43:46] ERROR[23473]: /usr/src/asterisk-1.4/include/asterisk/lock.h:370 __ast_pthread_mutex_lock: app_chanspy.c line 408 (chanspy_ds_free): '&chan->lock' really deep reentrancy!
[Feb 26 15:43:47] ERROR[23473]: /usr/src/asterisk-1.4/include/asterisk/lock.h:370 __ast_pthread_mutex_lock: app_chanspy.c line 408 (chanspy_ds_free): '&chan->lock' really deep reentrancy!
[Feb 26 15:43:47] NOTICE[23437]: chan_iax2.c:6701 socket_read: Out of idle IAX2 threads for I/O, pausing!
[Feb 26 15:43:47] ERROR[23473]: /usr/src/asterisk-1.4/include/asterisk/lock.h:370 __ast_pthread_mutex_lock: app_chanspy.c line 408 (chanspy_ds_free): '&chan->lock' really deep reentrancy!
[Feb 26 15:43:47] ERROR[23473]: /usr/src/asterisk-1.4/include/asterisk/lock.h:370 __ast_pthread_mutex_lock: app_chanspy.c line 408 (chanspy_ds_free): '&chan->lock' really deep reentrancy!
[Feb 26 15:43:47] ERROR[23473]: /usr/src/asterisk-1.4/include/asterisk/lock.h:370 __ast_pthread_mutex_lock: app_chanspy.c line 408 (chanspy_ds_free): '&chan->lock' really deep reentrancy!
[Feb 26 15:43:47] ERROR[23473]: /usr/src/asterisk-1.4/include/asterisk/lock.h:370 __ast_pthread_mutex_lock: app_chanspy.c line 408 (chanspy_ds_free): '&chan->lock' really deep reentrancy!
[Feb 26 15:43:47] ERROR[23473]: /usr/src/asterisk-1.4/include/asterisk/lock.h:370 __ast_pthread_mutex_lock: app_chanspy.c line 408 (chanspy_ds_free): '&chan->lock' really deep reentrancy!
[Feb 26 15:43:47] ERROR[23473]: /usr/src/asterisk-1.4/include/asterisk/lock.h:370 __ast_pthread_mutex_lock: app_chanspy.c line 408 (chanspy_ds_free): '&chan->lock' really deep reentrancy!
[Feb 26 15:43:47] ERROR[23473]: /usr/src/asterisk-1.4/include/asterisk/lock.h:370 __ast_pthread_mutex_lock: app_chanspy.c line 408 (chanspy_ds_free): '&chan->lock' really deep reentrancy!

Comments: By: Digium Subversion (svnbot) 2008-02-26 19:11:29.000-0600

Repository: asterisk
Revision: 104334

U branches/1.4/apps/app_chanspy.c

------------------------------------------------------------------------
r104334 | russell | 2008-02-26 19:11:24 -0600 (Tue, 26 Feb 2008) | 3 lines

Avoid some recursion in the cleanup code for the chanspy datastore
(closes issue ASTERISK-11517, reported by junky, patched by me)

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=104334
By: Digium Subversion (svnbot) 2008-02-26 19:12:29.000-0600

Repository: asterisk
Revision: 104335

_U trunk/
U trunk/apps/app_chanspy.c

------------------------------------------------------------------------
r104335 | russell | 2008-02-26 19:12:27 -0600 (Tue, 26 Feb 2008) | 11 lines

Merged revisions 104334 via svnmerge from
https://origsvn.digium.com/svn/asterisk/branches/1.4

........
r104334 | russell | 2008-02-26 19:15:02 -0600 (Tue, 26 Feb 2008) | 3 lines

Avoid some recursion in the cleanup code for the chanspy datastore
(closes issue ASTERISK-11517, reported by junky, patched by me)

........

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=104335
By: Clod Patry (junky) 2008-02-27 09:25:42.000-0600

I still have the same bad behavior.
Here's some infos with recent patch.

localhost*CLI> core show locks
localhost*CLI>
=======================================================================
=== Currently Held Locks ==============================================
=======================================================================
===
=== <file> <line num> <function> <lock name> <lock addr> (times locked)
===
=== Thread ID: 3085982624 (listener started at [ 1063] asterisk.c ast_makesocket())
=== -------------------------------------------------------------------
===
=== Thread ID: 3085724576 (do_devstate_changes started at [ 386] devicestate.c ast_device_state_engine_init())
=== -------------------------------------------------------------------
===
=== Thread ID: 3085474720 (netconsole started at [ 1005] asterisk.c listener())
=== -------------------------------------------------------------------
===
=== Thread ID: 3083860896 (do_parking_thread started at [ 2456] res_features.c load_module())
=== -------------------------------------------------------------------
===
=== Thread ID: 3083615136 (ctiServerReceiver started at [ 4161] app_ahEventsProxy.c load_module())
=== -------------------------------------------------------------------
===
=== Thread ID: 2558876576 (do_monitor started at [ 7019] chan_zap.c restart_monitor())
=== -------------------------------------------------------------------
===
=== Thread ID: 2558630816 (scan_thread started at [ 499] pbx_spool.c load_module())
=== -------------------------------------------------------------------
===
=== Thread ID: 2558385056 (sla_thread started at [ 4844] app_meetme.c sla_load_config())
=== -------------------------------------------------------------------
===
=== Thread ID: 2558139296 (do_monitor started at [15701] chan_sip.c restart_monitor())
=== -------------------------------------------------------------------
===
=== Thread ID: 2557893536 (wrapupchecker_thread started at [ 7439] app_AheevaPhoneSimulator.c load_module())
=== -------------------------------------------------------------------
===
=== Thread ID: 2557647776 (recording_sender_thread started at [ 7441] app_AheevaPhoneSimulator.c load_module())
=== -------------------------------------------------------------------
===
=== Thread ID: 2557402016 (communication_server_thread started at [ 7470] app_AheevaPhoneSimulator.c load_module())
=== -------------------------------------------------------------------
===
=== Thread ID: 2557156256 (iax2_process_thread started at [ 8883] chan_iax2.c start_network_thread())
=== -------------------------------------------------------------------
===
=== Thread ID: 2556910496 (iax2_process_thread started at [ 8883] chan_iax2.c start_network_thread())
=== -------------------------------------------------------------------
===
=== Thread ID: 2556664736 (iax2_process_thread started at [ 8883] chan_iax2.c start_network_thread())
=== -------------------------------------------------------------------
===
=== Thread ID: 2556418976 (iax2_process_thread started at [ 8883] chan_iax2.c start_network_thread())
=== -------------------------------------------------------------------
===
=== Thread ID: 2556173216 (iax2_process_thread started at [ 8883] chan_iax2.c start_network_thread())
=== -------------------------------------------------------------------
===
=== Thread ID: 2555681696 (iax2_process_thread started at [ 8883] chan_iax2.c start_network_thread())
=== -------------------------------------------------------------------
===
=== Thread ID: 2555927456 (iax2_process_thread started at [ 8883] chan_iax2.c start_network_thread())
=== -------------------------------------------------------------------
===
=== Thread ID: 2555435936 (iax2_process_thread started at [ 8883] chan_iax2.c start_network_thread())
=== -------------------------------------------------------------------
===
=== Thread ID: 2555190176 (iax2_process_thread started at [ 8883] chan_iax2.c start_network_thread())
=== -------------------------------------------------------------------
===
=== Thread ID: 2554944416 (iax2_process_thread started at [ 8883] chan_iax2.c start_network_thread())
=== -------------------------------------------------------------------
===
=== Thread ID: 2554698656 (sched_thread started at [ 8893] chan_iax2.c start_network_thread())
=== -------------------------------------------------------------------
===
=== Thread ID: 2554452896 (network_thread started at [ 8894] chan_iax2.c start_network_thread())
=== -------------------------------------------------------------------
===
=== Thread ID: 2554166176 (monitor_sig_flags started at [ 3001] asterisk.c main())
=== -------------------------------------------------------------------
===
=== Thread ID: 2553920416 (pbx_thread started at [ 2647] pbx.c ast_pbx_start())
=== ---> Lock #0 (chan_agent.c): MUTEX 2181 __login_exec &p->app_lock 0x88f2308 (1)
=== -------------------------------------------------------------------
===
=== Thread ID: 2553670560 (autoservice_run started at [ 194] autoservice.c ast_autoservice_start())
=== -------------------------------------------------------------------
===
=== Thread ID: 3085228960 (netconsole started at [ 1005] asterisk.c listener())
=== -------------------------------------------------------------------
===
=== Thread ID: 2553424800 (pbx_thread started at [ 2647] pbx.c ast_pbx_start())
=== ---> Lock #0 (app_chanspy.c): MUTEX 401 chanspy_ds_free &chanspy_ds->lock 0x9831d854 (1)
=== ---> Waiting for Lock #1 (app_chanspy.c): MUTEX 408 chanspy_ds_free &chan->lock 0x8929310 (1)
=== -------------------------------------------------------------------
===
=======================================================================

but i often see the latest thread changing for:

=== -------------------------------------------------------------------
===
=== Thread ID: 2553424800 (pbx_thread started at [ 2647] pbx.c ast_pbx_start())
=== ---> Lock #0 (app_chanspy.c): MUTEX 401 chanspy_ds_free &chanspy_ds->lock 0x9831d854 (1)
=== ---> Waiting for Lock #1 (app_chanspy.c): MUTEX 408 chanspy_ds_free &chan->lock 0x8929310 (1)
=== -------------------------------------------------------------------
===
=======================================================================

By: Clod Patry (junky) 2008-02-27 09:41:40.000-0600

Also, if i go on the right thread in gdb:

(gdb) thread 2
[Switching to thread 2 (Thread -1741542496 (LWP 32256))]#0 0x0081207a in pthread_mutex_trylock () from /lib/tls/libpthread.so.0
(gdb) bt
#0 0x0081207a in pthread_mutex_trylock () from /lib/tls/libpthread.so.0
#1 0x08086c13 in __ast_pthread_mutex_trylock (filename=0x814dd14 "channel.c", lineno=1065, func=0x814f24c "channel_find_locked", mutex_name=0x814f27a "&c->lock", t=0x8929310)
at /usr/src/asterisk-1.4/include/asterisk/lock.h:410
#2 0x08087034 in channel_find_locked (prev=0x0, name=0x0, namelen=0, context=0x0, exten=0x0) at channel.c:1065
#3 0x0808755b in ast_channel_walk_locked (prev=0x0) at channel.c:1188
#4 0x00b1142d in next_channel (chan=0x8929298, last=0x0, spec=0x0, exten=0x0, context=0x0, chanspy_ds=0x9831d850) at app_chanspy.c:457
ASTERISK-1 0x00b11ea5 in common_exec (chan=0x8929298, flags=0x9831ddf8, volfactor=0, fd=0, mygroup=0x0, spec=0x0, exten=0x0, context=0x0) at app_chanspy.c:517
ASTERISK-2 0x00b1285d in chanspy_exec (chan=0x8929298, data=0x9831db90) at app_chanspy.c:719
ASTERISK-3 0x080d396b in pbx_exec (c=0x8929298, app=0x88ea040, data=0x9831ff50) at pbx.c:532
ASTERISK-4 0x080d7570 in pbx_extension_helper (c=0x8929298, con=0x0, context=0x89294d8 "aheeva", exten=0x8929528 "601", priority=1, label=0x0, callerid=0x891dd70 "5556", action=E_SPAWN) at pbx.c:1851
ASTERISK-5 0x080d88a0 in ast_spawn_extension (c=0x8929298, context=0x89294d8 "aheeva", exten=0x8929528 "601", priority=1, callerid=0x891dd70 "5556") at pbx.c:2306
ASTERISK-6 0x080d8dea in __ast_pbx_run (c=0x8929298) at pbx.c:2408
ASTERISK-7 0x080d9ba7 in pbx_thread (data=0x8929298) at pbx.c:2623
ASTERISK-8 0x0811af5a in dummy_start (data=0x89245c8) at utils.c:861
ASTERISK-9 0x008103cc in start_thread () from /lib/tls/libpthread.so.0
ASTERISK-10 0x006e91ae in clone () from /lib/tls/libc.so.6

frame 4 is odd:
last=0x0, spec=0x0, exten=0x0, context=0x0

(gdb) frame 4
#4 0x00b1142d in next_channel (chan=0x8929298, last=0x0, spec=0x0, exten=0x0, context=0x0, chanspy_ds=0x9831d850) at app_chanspy.c:457
457 this = ast_channel_walk_locked(last);
(gdb)

By: Digium Subversion (svnbot) 2008-02-27 11:29:51.000-0600

Repository: asterisk
Revision: 104625

U branches/1.4/apps/app_chanspy.c

------------------------------------------------------------------------
r104625 | russell | 2008-02-27 11:29:50 -0600 (Wed, 27 Feb 2008) | 4 lines

Fix a problem in ChanSpy where it could get stuck in an infinite loop without
being able to detect that the calling channel hung up.
(closes issue ASTERISK-11517, reported by junky, patched by me)

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=104625
By: Digium Subversion (svnbot) 2008-02-27 11:34:07.000-0600

Repository: asterisk
Revision: 104643

_U trunk/
U trunk/apps/app_chanspy.c

------------------------------------------------------------------------
r104643 | russell | 2008-02-27 11:34:06 -0600 (Wed, 27 Feb 2008) | 12 lines

Merged revisions 104625 via svnmerge from
https://origsvn.digium.com/svn/asterisk/branches/1.4

........
r104625 | russell | 2008-02-27 11:33:04 -0600 (Wed, 27 Feb 2008) | 4 lines

Fix a problem in ChanSpy where it could get stuck in an infinite loop without
being able to detect that the calling channel hung up.
(closes issue ASTERISK-11517, reported by junky, patched by me)

........

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=104643