ASTERISK-14113: [patch] chan_sip random deadlock

[Home]

Summary: ASTERISK-14113: [patch] chan_sip random deadlock

Reporter: ktsaou (ktsaou) Labels:

Date Opened: 2009-05-12 16:53:00 Date Closed: 2011-06-07 14:00:18

Priority: Critical Regression? No

Status: Closed/Complete Components: Channels/chan_sip/General

Versions: Frequency of
Occurrence

Related
Issues:

Environment: Attachments: ( 0) 20090514__issue15090__1.4.diff.txt
( 1) 20090514__issue15090__1.6.0.diff.txt
( 2) 20090514__issue15090__trunk.diff.txt
( 3) 20090514__issue15090.diff.txt

Description: I have asterisk installed on a 64-bit debian 5.0, with realtime config for sip peers.

Asterisk randomly stops processing SIP calls. I cannot find a pattern of external events triggering it.

When this happens chan_sip appears totally frozen and even established calls stop routing RTP.

I have compiled asterisk with all debuging input enabled. When this happers 'core show locks' presents this:

=======================================================================
=== Currently Held Locks ==============================================
=======================================================================
===
=== <pending> <lock#> (<file>): <lock type> <line num> <function> <lock name> <lock addr> (times locked)
===
=== Thread ID: 1091053904 (do_monitor started at [20435] chan_sip.c restart_monitor())
=== ---> Lock #0 (chan_sip.c): MUTEX 19947 handle_request_do &netlock 0x7f9b9e2e6c00 (1)
/opt/voip/asterisk-1.6.1.0/sbin/asterisk(ast_bt_get_addresses+0x1a) [0x4c6870]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7f9b9e0655b7]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7f9b9e0ba9d8]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7f9b9e0ba79e]
/opt/voip/asterisk-1.6.1.0/sbin/asterisk(ast_io_wait+0x1ba) [0x4bbf30]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7f9b9e0bc18d]
/opt/voip/asterisk-1.6.1.0/sbin/asterisk [0x53f973]
/lib/libpthread.so.0 [0x7f9b9f63ffc7]
/lib/libc.so.6(clone+0x6d) [0x7f9b9fb285ad]
=== ---> Lock #1 (chan_sip.c): MUTEX 6464 find_call sip_pvt_ptr 0x7f9b984a1460 (1)
/opt/voip/asterisk-1.6.1.0/sbin/asterisk(ast_bt_get_addresses+0x1a) [0x4c6870]
/opt/voip/asterisk-1.6.1.0/sbin/asterisk [0x442f79]
/opt/voip/asterisk-1.6.1.0/sbin/asterisk(_ao2_lock+0x53) [0x442e15]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7f9b9e078d60]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7f9b9e0ba9ec]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7f9b9e0ba79e]
/opt/voip/asterisk-1.6.1.0/sbin/asterisk(ast_io_wait+0x1ba) [0x4bbf30]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7f9b9e0bc18d]
/opt/voip/asterisk-1.6.1.0/sbin/asterisk [0x53f973]
/lib/libpthread.so.0 [0x7f9b9f63ffc7]
/lib/libc.so.6(clone+0x6d) [0x7f9b9fb285ad]
=== -------------------------------------------------------------------
===
=======================================================================

Please advice...

Comments: By: Tilghman Lesher (tilghman) 2009-05-13 15:18:37

Marked private by request, due to sensitive data in the backtrace.
By: ktsaou (ktsaou) 2009-05-13 16:43:23

The attached files:

1. asterisk-trace-1.txt contains a trace when realtime is running with res_mysql.so

2. asterisk-trace-2-with-odbc.txt contains a trace when realtime is running with res_odbc.so

A few seconds before freezing sip, asterisk marked as unreachable most sip peers.
By: ktsaou (ktsaou) 2009-05-13 19:51:33

I tried to get a tcpdump of the traffic while asterisk was frozen every 10 minutes. I found that asterisk was flooding a peer with OPTIONS requests (qualify?).

I changed the option ignoreregexpire to 'no' (was 'yes') and now asterisk does not flood its peers any more. For the moment, it stopped freezing.
By: ktsaou (ktsaou) 2009-05-14 06:27:45

It still freezes randomly, but this time it complains about res_config_mysql (see bellow).
I have switched to odbc in hope it will solve the issue.

=======================================================================
=== Currently Held Locks ==============================================
=======================================================================
===
=== <pending> <lock#> (<file>): <lock type> <line num> <function> <lock name> <lock addr> (times locked)
===
=== Thread ID: 1092036944 (do_monitor started at [20435] chan_sip.c restart_monitor())
=== ---> Lock #0 (chan_sip.c): MUTEX 19947 handle_request_do &netlock 0x7fe55ac36c00 (1)
/opt/voip/asterisk-1.6.1.0/sbin/asterisk(ast_bt_get_addresses+0x1a) [0x4c6870]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7fe55a9b55b7]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7fe55aa0a9d8]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7fe55aa0a79e]
/opt/voip/asterisk-1.6.1.0/sbin/asterisk(ast_io_wait+0x1ba) [0x4bbf30]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7fe55aa0c18d]
/opt/voip/asterisk-1.6.1.0/sbin/asterisk [0x53f973]
/lib/libpthread.so.0 [0x7fe55bf8ffc7]
/lib/libc.so.6(clone+0x6d) [0x7fe55c4785ad]
=== ---> Lock #1 (chan_sip.c): MUTEX 6464 find_call sip_pvt_ptr 0x7fe5380d6990 (1)
/opt/voip/asterisk-1.6.1.0/sbin/asterisk(ast_bt_get_addresses+0x1a) [0x4c6870]
/opt/voip/asterisk-1.6.1.0/sbin/asterisk [0x442f79]
/opt/voip/asterisk-1.6.1.0/sbin/asterisk(_ao2_lock+0x53) [0x442e15]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7fe55a9c8d60]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7fe55aa0a9ec]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7fe55aa0a79e]
/opt/voip/asterisk-1.6.1.0/sbin/asterisk(ast_io_wait+0x1ba) [0x4bbf30]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7fe55aa0c18d]
/opt/voip/asterisk-1.6.1.0/sbin/asterisk [0x53f973]
/lib/libpthread.so.0 [0x7fe55bf8ffc7]
/lib/libc.so.6(clone+0x6d) [0x7fe55c4785ad]
=== ---> Lock #2 (res_config_mysql.c): MUTEX 149 find_database &(&databases)->lock 0x7fe5427501b0 (1)
/opt/voip/asterisk-1.6.1.0/sbin/asterisk(ast_bt_get_addresses+0x1a) [0x4c6870]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/res_config_mysql.so [0x7fe542544fe3]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/res_config_mysql.so [0x7fe542546fde]
/opt/voip/asterisk-1.6.1.0/sbin/asterisk [0x47945c]
/opt/voip/asterisk-1.6.1.0/sbin/asterisk(ast_load_realtime+0xf2) [0x479644]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7fe55a9bc079]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7fe55a9bccbe]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7fe55aa0d652]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7fe55a9d6711]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7fe55aa0e3ab]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7fe55a9de046]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7fe55a9e0285]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7fe55aa08ea4]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7fe55aa09f1b]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7fe55aa0aef7]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7fe55aa0a79e]
/opt/voip/asterisk-1.6.1.0/sbin/asterisk(ast_io_wait+0x1ba) [0x4bbf30]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7fe55aa0c18d]
/opt/voip/asterisk-1.6.1.0/sbin/asterisk [0x53f973]
/lib/libpthread.so.0 [0x7fe55bf8ffc7]
/lib/libc.so.6(clone+0x6d) [0x7fe55c4785ad]
=== ---> Waiting for Lock #3 (res_config_mysql.c): MUTEX 152 find_database &cur->lock 0x7fe5540e1f58 (1)
/opt/voip/asterisk-1.6.1.0/sbin/asterisk(ast_bt_get_addresses+0x1a) [0x4c6870]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/res_config_mysql.so [0x7fe542545132]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/res_config_mysql.so [0x7fe542546fde]
/opt/voip/asterisk-1.6.1.0/sbin/asterisk [0x47945c]
/opt/voip/asterisk-1.6.1.0/sbin/asterisk(ast_load_realtime+0xf2) [0x479644]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7fe55a9bc079]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7fe55a9bccbe]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7fe55aa0d652]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7fe55a9d6711]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7fe55aa0e3ab]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7fe55a9de046]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7fe55a9e0285]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7fe55aa08ea4]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7fe55aa09f1b]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7fe55aa0aef7]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7fe55aa0a79e]
/opt/voip/asterisk-1.6.1.0/sbin/asterisk(ast_io_wait+0x1ba) [0x4bbf30]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7fe55aa0c18d]
/opt/voip/asterisk-1.6.1.0/sbin/asterisk [0x53f973]
/lib/libpthread.so.0 [0x7fe55bf8ffc7]
/lib/libc.so.6(clone+0x6d) [0x7fe55c4785ad]
=== --- ---> Locked Here: res_config_mysql.c line 152 (find_database)
=== -------------------------------------------------------------------
===
=== Thread ID: 1092282704 (do_devstate_changes started at [ 752] devicestate.c ast_device_state_engine_init())
=== ---> Lock #0 (res_config_mysql.c): MUTEX 152 find_database &cur->lock 0x7fe5540e1f58 (1)
/opt/voip/asterisk-1.6.1.0/sbin/asterisk(ast_bt_get_addresses+0x1a) [0x4c6870]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/res_config_mysql.so [0x7fe542545132]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/res_config_mysql.so [0x7fe54254cb0f]
/opt/voip/asterisk-1.6.1.0/sbin/asterisk(ast_update_realtime+0x1ef) [0x479e84]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7fe55a9dc01f]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7fe55aa14957]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7fe55a9bc6fc]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7fe55a9bccbe]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7fe55aa0e6f9]
/opt/voip/asterisk-1.6.1.0/sbin/asterisk [0x47e648]
/opt/voip/asterisk-1.6.1.0/sbin/asterisk [0x47f47d]
/opt/voip/asterisk-1.6.1.0/sbin/asterisk [0x480183]
/opt/voip/asterisk-1.6.1.0/sbin/asterisk [0x53f973]
/lib/libpthread.so.0 [0x7fe55bf8ffc7]
/lib/libc.so.6(clone+0x6d) [0x7fe55c4785ad]
=== ---> Lock #1 (res_config_mysql.c): MUTEX 201 find_table &table->lock 0x23448c0 (1)
/opt/voip/asterisk-1.6.1.0/sbin/asterisk(ast_bt_get_addresses+0x1a) [0x4c6870]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/res_config_mysql.so [0x7fe542548f76]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/res_config_mysql.so [0x7fe54254cb38]
/opt/voip/asterisk-1.6.1.0/sbin/asterisk(ast_update_realtime+0x1ef) [0x479e84]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7fe55a9dc01f]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7fe55aa14957]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7fe55a9bc6fc]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7fe55a9bccbe]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7fe55aa0e6f9]
/opt/voip/asterisk-1.6.1.0/sbin/asterisk [0x47e648]
/opt/voip/asterisk-1.6.1.0/sbin/asterisk [0x47f47d]
/opt/voip/asterisk-1.6.1.0/sbin/asterisk [0x480183]
/opt/voip/asterisk-1.6.1.0/sbin/asterisk [0x53f973]
/lib/libpthread.so.0 [0x7fe55bf8ffc7]
/lib/libc.so.6(clone+0x6d) [0x7fe55c4785ad]
=== ---> Waiting for Lock #2 (res_config_mysql.c): MUTEX 149 find_database &(&databases)->lock 0x7fe5427501b0 (1)
/opt/voip/asterisk-1.6.1.0/sbin/asterisk(ast_bt_get_addresses+0x1a) [0x4c6870]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/res_config_mysql.so [0x7fe542544fe3]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/res_config_mysql.so [0x7fe542548095]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/res_config_mysql.so [0x7fe54254a930]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/res_config_mysql.so [0x7fe54254c088]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/res_config_mysql.so [0x7fe54254cce9]
/opt/voip/asterisk-1.6.1.0/sbin/asterisk(ast_update_realtime+0x1ef) [0x479e84]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7fe55a9dc01f]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7fe55aa14957]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7fe55a9bc6fc]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7fe55a9bccbe]
/opt/voip/asterisk-1.6.1.0//lib/asterisk/modules/chan_sip.so [0x7fe55aa0e6f9]
/opt/voip/asterisk-1.6.1.0/sbin/asterisk [0x47e648]
/opt/voip/asterisk-1.6.1.0/sbin/asterisk [0x47f47d]
/opt/voip/asterisk-1.6.1.0/sbin/asterisk [0x480183]
/opt/voip/asterisk-1.6.1.0/sbin/asterisk [0x53f973]
/lib/libpthread.so.0 [0x7fe55bf8ffc7]
/lib/libc.so.6(clone+0x6d) [0x7fe55c4785ad]
=== --- ---> Locked Here: res_config_mysql.c line 149 (find_database)
=== -------------------------------------------------------------------
===
=======================================================================
By: Tilghman Lesher (tilghman) 2009-05-14 12:13:42

Patch uploaded for the deadlock above.
By: Tilghman Lesher (tilghman) 2009-05-14 14:00:35

Possible patches also uploaded for the other problem, now that you've identified a direct link to an option. The patch for trunk also applies to 1.6.1 and 1.6.2.
By: Tilghman Lesher (tilghman) 2009-05-14 14:03:33

I have deleted the backtraces with sensitive information, and marked this issue once again as public.
By: Digium Subversion (svnbot) 2009-05-14 14:17:00

Repository: asterisk-addons
Revision: 910

U trunk/res/res_config_mysql.c

------------------------------------------------------------------------
r910 | tilghman | 2009-05-14 14:17:00 -0500 (Thu, 14 May 2009) | 7 lines

Change database list to be rwlist locks, to avoid a potential deadlock between 2 readers.
(closes issue ASTERISK-14058, related to issue ASTERISK-14113)
Reported by: cristiandimache
Patches:
20090514__issue15090.diff.txt uploaded by tilghman (license 14)
Tested by: cristiandimache

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

http://svn.digium.com/view/asterisk-addons?view=rev&revision=910
By: Digium Subversion (svnbot) 2009-05-14 14:19:51

Repository: asterisk-addons
Revision: 913

_U branches/1.6.1/
U branches/1.6.1/res/res_config_mysql.c

------------------------------------------------------------------------
r913 | tilghman | 2009-05-14 14:19:50 -0500 (Thu, 14 May 2009) | 14 lines

Merged revisions 910 via svnmerge from
https://origsvn.digium.com/svn/asterisk-addons/trunk

........
r910 | tilghman | 2009-05-14 14:16:53 -0500 (Thu, 14 May 2009) | 7 lines

Change database list to be rwlist locks, to avoid a potential deadlock between 2 readers.
(closes issue ASTERISK-14058, related to issue ASTERISK-14113)
Reported by: cristiandimache
Patches:
20090514__issue15090.diff.txt uploaded by tilghman (license 14)
Tested by: cristiandimache
........

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

http://svn.digium.com/view/asterisk-addons?view=rev&revision=913
By: Digium Subversion (svnbot) 2009-05-14 14:21:20

Repository: asterisk-addons
Revision: 914

_U branches/1.6.2/
U branches/1.6.2/res/res_config_mysql.c

------------------------------------------------------------------------
r914 | tilghman | 2009-05-14 14:21:20 -0500 (Thu, 14 May 2009) | 14 lines

Merged revisions 910 via svnmerge from
https://origsvn.digium.com/svn/asterisk-addons/trunk

........
r910 | tilghman | 2009-05-14 14:16:53 -0500 (Thu, 14 May 2009) | 7 lines

Change database list to be rwlist locks, to avoid a potential deadlock between 2 readers.
(closes issue ASTERISK-14058, related to issue ASTERISK-14113)
Reported by: cristiandimache
Patches:
20090514__issue15090.diff.txt uploaded by tilghman (license 14)
Tested by: cristiandimache
........

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

http://svn.digium.com/view/asterisk-addons?view=rev&revision=914
By: Tilghman Lesher (tilghman) 2009-07-16 12:04:47

Given that you've changed your driver, and that you've reported no further problems, I am closing this issue as no longer reproducible. If this is not the case, please feel free to reopen this issue.