[Home]

Summary:ASTERISK-19775: Backgrace generation in Asterisk causes a seg fault
Reporter:Volker Kettenbach (vsauer)Labels:
Date Opened:2012-04-24 12:02:50Date Closed:2012-06-13 16:02:20
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Applications/app_dial Channels/chan_local
Versions:1.8.11.0 10.3.0 Frequency of
Occurrence		Constant
Related
Issues:
is a clone ofASTERISK-19611 SIP stack stops working (deadlock?) if a call to a snom phone is redirected by "302 Moved temporarily" to chan_local
Environment:Debian Stable 2.6.32-5-686 Snom 370 FW 8.4.31 Snom 320 FW 8.4.31 Snom m9 9.5.14-a Asterisk 10.3.0 and all versions between 1.8.8.0 and 1.8.11.0Attachments:( 0) 2012-04-20_asterisk-10.3.0-coredump_crash_on_302.backtrace.txt
( 1) 2012-04-20_asterisk-10.3.0-sipdebug.txt
( 2) asterisk-10.3.0-deadlock_on_302.core_show_locks.gdb_backtrace.txt
( 3) asterisk-10.3.0-deadlock_on_302.res_timing_dahdi.txt
( 4) asterisk-10.3.0-deadlock_on_302.res_timing_dahdi.txt
( 5) asterisk-10.3.0-deadlock_on_302.res_timing_timerfd.txt
( 6) asterisk-10.3.0-deadlock_on_302.sip_debug.core_crash.txt
( 7) asterisk-10.4.0-core-show-locks-patch-applied-backtrace.txt
Description:This might be the same as ASTERISK-17802

If I set a call forwarding of one of the snom phones either to another phone or to an external phone number, asterisk stops processing (sip) calls and the call itself is either interupted after a few parts of a second (if res_timing_timerfd) or is processed to it's normal ending (in case of res_timing_dahdi).

Here's what happens in CLI in case of res_timing_timerfd:

(See full output of CLI, core show locks and dgb  threads in attachments)

{noformat}
[....]
[Mar 31 12:44:24]     -- SIP/snomm9-2-00000008 answered Local/85@doLocalCallsPrivat-2130;2
[Mar 31 12:44:24]   == Extension Changed 85[incoming] new state InUse for Notify User snomvs
[Mar 31 12:44:24]   == Extension Changed 85[incoming] new state InUse for Notify User snomhmk
[Mar 31 12:44:24]     -- Local/85@doLocalCallsPrivat-2130;1 answered SIP/sipgate-gmbh-e0-00000006
[Mar 31 12:44:24]   == Spawn extension (macro-CallInt2Int, s, 5) exited non-zero on 'Local/85@doLocalCallsPrivat-2130;2' in macro 'CallInt2Int'
[Mar 31 12:44:24]   == Spawn extension (incoming, 85, 100) exited non-zero on 'Local/85@doLocalCallsPrivat-2130;2'
[Mar 31 12:44:24] ERROR[7261]: lock.c:280 __ast_pthread_mutex_lock: audiohook.c line 842 (audio_audiohook_write_list): Error obtaining mutex: Invalid argument
[Mar 31 12:44:24] ERROR[7261]: lock.c:407 __ast_pthread_mutex_unlock: audiohook.c line 861 (audio_audiohook_write_list): mutex '&(audiohook)->lock' freed more times than we've locked!
[Mar 31 12:44:24] ERROR[7261]: lock.c:438 __ast_pthread_mutex_unlock: audiohook.c line 861 (audio_audiohook_write_list): Error releasing mutex: Invalid argument


[Message repeated ~ 100 times]


[Asterisk stopped processing (sip) calls]
{noformat}

*CLI> core show locks

{noformat}
=======================================================================
=== Currently Held Locks ==============================================
=======================================================================
===
=== <pending> <lock#> (<file>): <lock type> <line num> <function> <lock name> <lock addr> (times locked)
===
=== Thread ID: 0xaefffb70 (pbx_thread           started at [ 5512] pbx.c ast_pbx_start())
=== ---> Lock #0 (channel.c): MUTEX 4852 ast_write chan 0x875a3d8 (1)
   /opt/asterisk/sbin/asterisk(ast_bt_get_addresses+0x1a) [0x812c8aa]
   /opt/asterisk/sbin/asterisk(__ast_pthread_mutex_trylock+0x77) [0x8129fc7]
   /opt/asterisk/sbin/asterisk(ast_write+0x37) [0x80bd017]
   /opt/asterisk/sbin/asterisk() [0x80c47a2]
   /opt/asterisk/sbin/asterisk(ast_channel_bridge+0x6d6) [0x80c54a6]
   /opt/asterisk/sbin/asterisk(ast_bridge_call+0x341) [0x80fa2e1]
   /opt/asterisk/lib/asterisk/modules/app_dial.so(+0xc05d) [0xb67a105d]
   /opt/asterisk/lib/asterisk/modules/app_dial.so(+0xda1d) [0xb67a2a1d]
   /opt/asterisk/sbin/asterisk(pbx_exec+0x10b) [0x8154bdb]
   /opt/asterisk/sbin/asterisk() [0x816305b]
   /opt/asterisk/lib/asterisk/modules/app_macro.so(+0x248b) [0xb675c48b]
   /opt/asterisk/sbin/asterisk(pbx_exec+0x10b) [0x8154bdb]
   /opt/asterisk/sbin/asterisk() [0x816305b]
   /opt/asterisk/sbin/asterisk() [0x81697ed]
   /opt/asterisk/sbin/asterisk() [0x816b1de]
   /opt/asterisk/sbin/asterisk() [0x81af8ce]
   /lib/i686/cmov/libpthread.so.0(+0x5955) [0xb751c955]
   /lib/i686/cmov/libc.so.6(clone+0x5e) [0xb769058e]
=== -------------------------------------------------------------------
===
=======================================================================
{noformat}



In case of res_timing_dahdi:

{noformat}
[Mar 31 13:23:06] VERBOSE[18249] app_dial.c: [Mar 31 13:23:06]     -- Called SIP/snomm9-2
[Mar 31 13:23:06] VERBOSE[18249] app_dial.c: [Mar 31 13:23:06]     -- SIP/snomm9-2-00000002 is ringing
[Mar 31 13:23:06] VERBOSE[18246] app_dial.c: [Mar 31 13:23:06]     -- Local/85@doLocalCallsPrivat-ad88;1 is ringing
[Mar 31 13:23:14] VERBOSE[18249] app_dial.c: [Mar 31 13:23:14]     -- SIP/snomm9-2-00000002 answered Local/85@doLocalCallsPrivat-ad88;2
[Mar 31 13:23:14] VERBOSE[18246] app_dial.c: [Mar 31 13:23:14]     -- Local/85@doLocalCallsPrivat-ad88;1 answered SIP/sipgate-gmbh-e0-00000000
[Mar 31 13:23:14] VERBOSE[18249] app_macro.c: [Mar 31 13:23:14]   == Spawn extension (macro-CallInt2Int, s, 5) exited non-zero on 'Local/85@doLocalCallsPrivat-
ad88;2' in macro 'CallInt2Int'
[Mar 31 13:23:14] VERBOSE[18249] pbx.c: [Mar 31 13:23:14]   == Spawn extension (incoming, 85, 100) exited non-zero on 'Local/85@doLocalCallsPrivat-ad88;2'
[Mar 31 13:23:40] ERROR[18246]: lock.c:280 __ast_pthread_mutex_lock: audiohook.c line 842 (audio_audiohook_write_list): Error obtaining mutex: Invalid argument
[Mar 31 13:23:40] ERROR[18246]: lock.c:407 __ast_pthread_mutex_unlock: audiohook.c line 861 (audio_audiohook_write_list): mutex '&(audiohook)->lock' freed more times than we've locked!
[Mar 31 13:23:40] ERROR[18246]: lock.c:438 __ast_pthread_mutex_unlock: audiohook.c line 861 (audio_audiohook_write_list): Error releasing mutex: Invalid argument
[Mar 31 13:23:40] ERROR[18246]: lock.c:280 __ast_pthread_mutex_lock: audiohook.c line 842 (audio_audiohook_write_list): Error obtaining mutex: Invalid argument
[Mar 31 13:23:40] ERROR[18246]: lock.c:407 __ast_pthread_mutex_unlock: audiohook.c line 861 (audio_audiohook_write_list): mutex '&(audiohook)->lock' freed more times than we've locked!
[Mar 31 13:23:40] ERROR[18246]: lock.c:438 __ast_pthread_mutex_unlock: audiohook.c line 861 (audio_audiohook_write_list): Error releasing mutex: Invalid argument
[Mar 31 13:23:40] ERROR[18246]: lock.c:280 __ast_pthread_mutex_lock: audiohook.c line 480 (ast_audiohook_update_status): Error obtaining mutex: Invalid argument


[Message repeated thousands of times]

[Asterisk stopped processing (sip) calls]
{noformat}

*CLI> core show locks

{noformat}
=======================================================================
=== Currently Held Locks ==============================================
=======================================================================
===
=== <pending> <lock#> (<file>): <lock type> <line num> <function> <lock name> <lock addr> (times locked)
===
=== Thread ID: 0xaf3d9b70 (do_monitor           started at [26703] chan_sip.c restart_monitor())
=== ---> Lock #0 (chan_sip.c): MUTEX 26675 do_monitor &monlock 0xb68673c0 (1)
   /opt/asterisk/sbin/asterisk(ast_bt_get_addresses+0x1a) [0x812c8aa]
   /opt/asterisk/sbin/asterisk(__ast_pthread_mutex_lock+0x7c) [0x812902c]
   /opt/asterisk/lib/asterisk/modules/chan_sip.so(+0x66832) [0xb6816832]
   /opt/asterisk/sbin/asterisk() [0x81af8ce]
   /lib/i686/cmov/libpthread.so.0(+0x5955) [0xb7525955]
   /lib/i686/cmov/libc.so.6(clone+0x5e) [0xb769958e]
=== ---> Waiting for Lock #1 (chan_sip.c): MUTEX 8175 sip_pvt_lock_full chan 0xa390928 (1)
   /opt/asterisk/sbin/asterisk(ast_bt_get_addresses+0x1a) [0x812c8aa]
   /opt/asterisk/sbin/asterisk(__ast_pthread_mutex_lock+0x7c) [0x812902c]
   /opt/asterisk/lib/asterisk/modules/chan_sip.so(+0xd0ca) [0xb67bd0ca]
   /opt/asterisk/lib/asterisk/modules/chan_sip.so(+0x89149) [0xb6839149]
   /opt/asterisk/sbin/asterisk(ast_sched_runq+0x14d) [0x81952bd]
   /opt/asterisk/lib/asterisk/modules/chan_sip.so(+0x6683f) [0xb681683f]
   /opt/asterisk/sbin/asterisk() [0x81af8ce]
   /lib/i686/cmov/libpthread.so.0(+0x5955) [0xb7525955]
   /lib/i686/cmov/libc.so.6(clone+0x5e) [0xb769958e]
=== --- ---> Locked Here: channel.c line 2832 (ast_hangup)
=== -------------------------------------------------------------------
===
=== Thread ID: 0xaf0dab70 (pbx_thread           started at [ 5512] pbx.c ast_pbx_start())
=== ---> Lock #0 (channel.c): MUTEX 2832 ast_hangup chan 0xa390928 (1)
   /opt/asterisk/sbin/asterisk(ast_bt_get_addresses+0x1a) [0x812c8aa]
   /opt/asterisk/sbin/asterisk(__ast_pthread_mutex_lock+0x7c) [0x812902c]
   /opt/asterisk/sbin/asterisk(ast_hangup+0x1de) [0x80bf66e]
   /opt/asterisk/lib/asterisk/modules/app_dial.so(+0xbd1b) [0xb676dd1b]
   /opt/asterisk/lib/asterisk/modules/app_dial.so(+0xda1d) [0xb676fa1d]
   /opt/asterisk/sbin/asterisk(pbx_exec+0x10b) [0x8154bdb]
   /opt/asterisk/sbin/asterisk() [0x816305b]
   /opt/asterisk/lib/asterisk/modules/app_macro.so(+0x248b) [0xb672948b]
   /opt/asterisk/sbin/asterisk(pbx_exec+0x10b) [0x8154bdb]
   /opt/asterisk/sbin/asterisk() [0x816305b]
   /opt/asterisk/sbin/asterisk() [0x81697ed]
   /opt/asterisk/sbin/asterisk() [0x816b1de]
   /opt/asterisk/sbin/asterisk() [0x81af8ce]
   /lib/i686/cmov/libpthread.so.0(+0x5955) [0xb7525955]
   /lib/i686/cmov/libc.so.6(clone+0x5e) [0xb769958e]
=== -------------------------------------------------------------------
===
=======================================================================
{noformat}


Comments:By: Matt Jordan (mjordan) 2012-04-24 12:03:32.835-0500

Note that this issue, which was cloned from ASTERISK-19611, is to fix the backtrace crash generation problem, as shown in attachment 2012-04-20_asterisk-10.3.0-coredump_crash_on_302.backtrace.txt
By: David Woolley (davidw) 2012-04-25 05:22:31.377-0500

I've now found were I reported what I suspect to be this problem, before.  It is ASTERISK-17439.  It looks like it stalled, waiting for the original reporter to provide feedback on my patch.
By: Volker Kettenbach (vsauer) 2012-05-04 02:44:39.309-0500

I don't think the attached patch fpr 1.6 will work on 10.*
I you could write a patch for this that applies to 10.3 or 10.4 I could test it!
By: David Woolley (davidw) 2012-05-04 04:58:56.887-0500

There was also a patch for trunk, which was done after the 10.x series was started.  As I recall, I applied the 1.6.1 patch to trunk, to create that one, so I think even the 1.6 patch will would have taken.
By: Volker Kettenbach (vsauer) 2012-05-04 08:01:17.078-0500

I successfully applied the patch to 10.4.0

But core show locks after the 302 still crashed asterisk:

.....

times than we've locked!
[May  4 14:59:48] ERROR[20859]: lock.c:438 __ast_pthread_mutex_unlock: audiohook.c line 861 (audio_audiohook_write_list): Error releasing mutex: Invalid argument
[May  4 14:59:48] ERROR[20859]: lock.c:280 __ast_pthread_mutex_lock: audiohook.c line 480 (ast_audiohook_update_status): Error obtaining mutex: Invalid argument

*CLI>
*CLI> core show locks


And all these messages "Error releasing mutex: Invalid argument" are pretty scary as well.

Backtrace attached