[Home]

Summary:ASTERISK-19767: dead lock in res_config_pgsl while dialing SIP extension
Reporter:Marcello Ceschia (marcelloceschia)Labels:
Date Opened:2012-04-22 10:50:03Date Closed:2017-03-27 14:41:02
Priority:MajorRegression?
Status:Closed/CompleteComponents:Resources/res_config_pgsql
Versions:10.3.0 Frequency of
Occurrence
Related
Issues:
Environment:Linux asterisk 3.1.9-1.4-default #1 SMP Fri Jan 27 08:55:10 UTC 2012 (efb5ff4) i686 i686 i386 GNU/LinuxAttachments:
Description:{noformat}
=======================================================================
=== Currently Held Locks ==============================================
=======================================================================
===
=== <pending> <lock#> (<file>): <lock type> <line num> <function> <lock name> <lock addr> (times locked)
===
=== Thread ID: 0xb5752b70 (do_monitor           started at [26748] chan_sip.c restart_monitor())
=== ---> Lock #0 (chan_sip.c): MUTEX 26720 do_monitor &monlock 0xb6224920 (1)
       /usr/sbin/asterisk(ast_bt_get_addresses+0x18) [0x8131cf8]
       /usr/sbin/asterisk(__ast_pthread_mutex_lock+0x87) [0x812cd37]
       /usr/lib/asterisk/modules/chan_sip.so(+0x627ac) [0xb61ce7ac]
       /usr/sbin/asterisk() [0x81b0298]
       /lib/libpthread.so.0(+0x6a7d) [0xb7217a7d]
       /lib/libc.so.6(clone+0x5e) [0xb7554abe]
=== ---> Lock #1 (res_config_pgsql.c): MUTEX 488 realtime_pgsql &pgsql_lock 0xb7117140 (1)
       /usr/sbin/asterisk(ast_bt_get_addresses+0x18) [0x8131cf8]
       /usr/sbin/asterisk(__ast_pthread_mutex_lock+0x87) [0x812cd37]
       /usr/lib/asterisk/modules/res_config_pgsql.so(+0x4fc1) [0xb710bfc1]
       /usr/sbin/asterisk() [0x80d5970]
       /usr/sbin/asterisk(ast_load_realtime+0x14) [0x80dc3a4]
       /usr/lib/asterisk/modules/chan_sip.so(+0x6406c) [0xb61d006c]
       /usr/lib/asterisk/modules/chan_sip.so(+0x6e783) [0xb61da783]
       /usr/lib/asterisk/modules/chan_sip.so(+0x6fabf) [0xb61dbabf]
       /usr/sbin/asterisk(ast_sched_runq+0x13f) [0x8197a9f]
       /usr/lib/asterisk/modules/chan_sip.so(+0x627b7) [0xb61ce7b7]
       /usr/sbin/asterisk() [0x81b0298]
       /lib/libpthread.so.0(+0x6a7d) [0xb7217a7d]
       /lib/libc.so.6(clone+0x5e) [0xb7554abe]
=== -------------------------------------------------------------------
===
=== Thread ID: 0xb46f3b70 (pbx_thread           started at [ 5512] pbx.c ast_pbx_start())
=== ---> Waiting for Lock #0 (chan_sip.c): MUTEX 26737 restart_monitor &monlock 0xb6224920 (1)
       /usr/sbin/asterisk(ast_bt_get_addresses+0x18) [0x8131cf8]
       /usr/sbin/asterisk(__ast_pthread_mutex_lock+0x87) [0x812cd37]
       /usr/lib/asterisk/modules/chan_sip.so(+0x6ca24) [0xb61d8a24]
       /usr/sbin/asterisk(ast_request+0x216) [0x80bc566]
       /usr/lib/asterisk/modules/app_dial.so(+0x9aaf) [0xb6242aaf]
       /usr/lib/asterisk/modules/app_dial.so(+0xd88f) [0xb624688f]
       /usr/sbin/asterisk(pbx_exec+0x10e) [0x815a9ee]
       /usr/sbin/asterisk() [0x8165124]
       /usr/sbin/asterisk() [0x816a76d]
       /usr/sbin/asterisk() [0x816c0fe]
       /usr/sbin/asterisk() [0x81b0298]
       /lib/libpthread.so.0(+0x6a7d) [0xb7217a7d]
       /lib/libc.so.6(clone+0x5e) [0xb7554abe]
=== --- ---> Locked Here: chan_sip.c line 26720 (do_monitor)
=== -------------------------------------------------------------------
===
=======================================================================
{noformat}
Comments:By: Mark Murawski (kobaz) 2012-04-24 08:54:28.262-0500

Confirmed with IAX as well

{noformat}
Thread 11 (Thread 0xb55ffb70 (LWP 22861)):
#0  0xffffe424 in __kernel_vsyscall ()
#1  0xb750a746 in poll () from /lib/i386-linux-gnu/i686/cmov/libc.so.6
#2  0xb6c6ff25 in ?? () from /usr/lib/libpq.so.5
#3  0xb6c6fdd9 in ?? () from /usr/lib/libpq.so.5
#4  0xb6c6fc5a in ?? () from /usr/lib/libpq.so.5
#5  0xb6c6fc22 in ?? () from /usr/lib/libpq.so.5
#6  0xb6c6c091 in PQgetResult () from /usr/lib/libpq.so.5
#7  0xb6c6c75b in ?? () from /usr/lib/libpq.so.5
#8  0xb6c6c3ae in PQexec () from /usr/lib/libpq.so.5
#9  0xb6255a74 in pgsql_log (cdr=0xe8e5948) at cdr_pgsql.c:305
#10 0x080a1d4a in post_cdr (cdr=0xe8e5948) at cdr.c:1135
#11 0x080a26a7 in ast_cdr_detach (cdr=0xe8e5948) at cdr.c:1331
#12 0x080f434a in ast_bridge_call (chan=0xb567cb28, peer=0xb5660fa0, config=0xb55f7804) at features.c:4198
#13 0xb631c36b in dial_exec_full (chan=0xb567cb28, data=0xb55fa0ce "SIP/pbx-sip-t1-gw1/12126993242,120,U(CallRouter_Pickup)b(CallRouter_PreDialOut,s,1)",
   peerflags=0xb55f7c68, continue_exec=0x0) at app_dial.c:2877
#14 0xb631cd51 in dial_exec (chan=0xb567cb28, data=0xb55fa0ce "SIP/pbx-sip-t1-gw1/12126993242,120,U(CallRouter_Pickup)b(CallRouter_PreDialOut,s,1)")
   at app_dial.c:2977
#15 0x08133301 in pbx_exec (c=0xb567cb28, app=0xe88b9a8, data=0xb55fa0ce "SIP/pbx-sip-t1-gw1/12126993242,120,U(CallRouter_Pickup)b(CallRouter_PreDialOut,s,1)")
   at pbx.c:1422
#16 0xb6d384de in handle_exec (chan=0xb567cb28, agi=0xb55fa9d0, argc=3, argv=0xb55f9e4c) at res_agi.c:2561
#17 0xb6d3ab58 in agi_handle_command (chan=0xb567cb28, agi=0xb55fa9d0, buf=0xb55fa0c4 "EXEC", dead=0) at res_agi.c:3445
#18 0xb6d3b578 in run_agi (chan=0xb567cb28,
   request=0xb55fa930 "agi://127.0.0.1:2000/module=Core;component=CallRouter;action=DialOut;route=ld11;trunkGroup=pbx-sip-t1;number=912126993242",
   agi=0xb55fa9d0, pid=-1, status=0xb55fa9c4, dead=0, argc=1, argv=0xb55fa9e8) at res_agi.c:3640
#19 0xb6d3d70b in agi_exec_full (chan=0xb567cb28,
   data=0xb55fcd9c "agi://127.0.0.1:2000/module=Core;component=CallRouter;action=DialOut;route=ld11;trunkGroup=pbx-sip-t1;number=912126993242", enhanced=0,
   dead=0) at res_agi.c:4189
#20 0xb6d3d84f in agi_exec (chan=0xb567cb28,
---Type <return> to continue, or q <return> to quit---
   data=0xb55fcd9c "agi://127.0.0.1:2000/module=Core;component=CallRouter;action=DialOut;route=ld11;trunkGroup=pbx-sip-t1;number=912126993242")
   at res_agi.c:4224
#21 0x08133301 in pbx_exec (c=0xb567cb28, app=0xb6f79780,
   data=0xb55fcd9c "agi://127.0.0.1:2000/module=Core;component=CallRouter;action=DialOut;route=ld11;trunkGroup=pbx-sip-t1;number=912126993242") at pbx.c:1422
#22 0x0813bc25 in pbx_extension_helper (c=0xb567cb28, con=0x0, context=0xb567cea4 "dialOut", exten=0xb567cef4 "s", priority=6, label=0x0,
   callerid=0xb6f94c30 "8005551234", action=E_SPAWN, found=0xb55ff228, combined_find_spawn=1) at pbx.c:4119
#23 0x0813d820 in ast_spawn_extension (c=0xb567cb28, context=0xb567cea4 "dialOut", exten=0xb567cef4 "s", priority=6, callerid=0xb6f94c30 "8005551234",
   found=0xb55ff228, combined_find_spawn=1) at pbx.c:4744
#24 0x0813e118 in __ast_pbx_run (c=0xb567cb28, args=0x0) at pbx.c:4842
#25 0x0813faf7 in pbx_thread (data=0xb567cb28) at pbx.c:5193
#26 0x0818e5f9 in dummy_start (data=0xb56b59b8) at utils.c:1004
#27 0xb72dec39 in start_thread () from /lib/i386-linux-gnu/i686/cmov/libpthread.so.0
#28 0xb751812e in clone () from /lib/i386-linux-gnu/i686/cmov/libc.so.6

Thread 10 (Thread 0xb5587b70 (LWP 23472)):
#0  0xffffe424 in __kernel_vsyscall ()
#1  0xb72e5f02 in __lll_lock_wait () from /lib/i386-linux-gnu/i686/cmov/libpthread.so.0
#2  0xb72e13a9 in _L_lock_819 () from /lib/i386-linux-gnu/i686/cmov/libpthread.so.0
#3  0xb72e123b in pthread_mutex_lock () from /lib/i386-linux-gnu/i686/cmov/libpthread.so.0
#4  0xb75253e6 in pthread_mutex_lock () from /lib/i386-linux-gnu/i686/cmov/libc.so.6
#5  0x08116179 in __ast_pthread_mutex_lock (filename=0xb62574fc "cdr_pgsql.c", lineno=108, func=0xb625825a "pgsql_log", mutex_name=0xb625751d "&pgsql_lock",
   t=0xb6259500) at lock.c:244
#6  0xb625337d in pgsql_log (cdr=0xe992a38) at cdr_pgsql.c:108
#7  0x080a1d4a in post_cdr (cdr=0xe992a38) at cdr.c:1135
#8  0x080a26a7 in ast_cdr_detach (cdr=0xe992a38) at cdr.c:1331
#9  0x080f434a in ast_bridge_call (chan=0xb5c4de70, peer=0xe9f14c0, config=0xb557f804) at features.c:4198
#10 0xb631c36b in dial_exec_full (chan=0xb5c4de70, data=0xb55820ce "SIP/pbx-sip-t1-gw1/12129412800,120,U(CallRouter_Pickup)b(CallRouter_PreDialOut,s,1)",
   peerflags=0xb557fc68, continue_exec=0x0) at app_dial.c:2877
#11 0xb631cd51 in dial_exec (chan=0xb5c4de70, data=0xb55820ce "SIP/pbx-sip-t1-gw1/12129412800,120,U(CallRouter_Pickup)b(CallRouter_PreDialOut,s,1)")
   at app_dial.c:2977
#12 0x08133301 in pbx_exec (c=0xb5c4de70, app=0xe88b9a8, data=0xb55820ce "SIP/pbx-sip-t1-gw1/12129412800,120,U(CallRouter_Pickup)b(CallRouter_PreDialOut,s,1)")
   at pbx.c:1422
#13 0xb6d384de in handle_exec (chan=0xb5c4de70, agi=0xb55829d0, argc=3, argv=0xb5581e4c) at res_agi.c:2561
#14 0xb6d3ab58 in agi_handle_command (chan=0xb5c4de70, agi=0xb55829d0, buf=0xb55820c4 "EXEC", dead=0) at res_agi.c:3445
#15 0xb6d3b578 in run_agi (chan=0xb5c4de70,
   request=0xb5582930 "agi://127.0.0.1:2000/module=Core;component=CallRouter;action=DialOut;route=ld11;trunkGroup=pbx-sip-t1;number=912129412800",
   agi=0xb55829d0, pid=-1, status=0xb55829c4, dead=0, argc=1, argv=0xb55829e8) at res_agi.c:3640
#16 0xb6d3d70b in agi_exec_full (chan=0xb5c4de70,
   data=0xb5584d9c "agi://127.0.0.1:2000/module=Core;component=CallRouter;action=DialOut;route=ld11;trunkGroup=pbx-sip-t1;number=912129412800", enhanced=0,
   dead=0) at res_agi.c:4189
#17 0xb6d3d84f in agi_exec (chan=0xb5c4de70,
   data=0xb5584d9c "agi://127.0.0.1:2000/module=Core;component=CallRouter;action=DialOut;route=ld11;trunkGroup=pbx-sip-t1;number=912129412800")
   at res_agi.c:4224
#18 0x08133301 in pbx_exec (c=0xb5c4de70, app=0xb6f79780,
   data=0xb5584d9c "agi://127.0.0.1:2000/module=Core;component=CallRouter;action=DialOut;route=ld11;trunkGroup=pbx-sip-t1;number=912129412800") at pbx.c:1422
#19 0x0813bc25 in pbx_extension_helper (c=0xb5c4de70, con=0x0, context=0xb5c4e1ec "dialOut", exten=0xb5c4e23c "s", priority=6, label=0x0,
   callerid=0xb6fbc490 "\220¿Äµàêdµ\20", action=E_SPAWN, found=0xb5587228, combined_find_spawn=1) at pbx.c:4119
#20 0x0813d820 in ast_spawn_extension (c=0xb5c4de70, context=0xb5c4e1ec "dialOut", exten=0xb5c4e23c "s", priority=6, callerid=0xb6fbc490 "\220¿Äµàêdµ\20",
   found=0xb5587228, combined_find_spawn=1) at pbx.c:4744
#21 0x0813e118 in __ast_pbx_run (c=0xb5c4de70, args=0x0) at pbx.c:4842
#22 0x0813faf7 in pbx_thread (data=0xb5c4de70) at pbx.c:5193
#23 0x0818e5f9 in dummy_start (data=0xb5c07f08) at utils.c:1004
#24 0xb72dec39 in start_thread () from /lib/i386-linux-gnu/i686/cmov/libpthread.so.0
#25 0xb751812e in clone () from /lib/i386-linux-gnu/i686/cmov/libc.so.6
{noformat}

By: Mark Murawski (kobaz) 2012-04-24 10:16:52.315-0500

The solution is to make iax reload and sip reload, and anything that's reloading to make a new pg connection instead of using the shared one.
By: Matt Jordan (mjordan) 2012-04-24 14:00:29.363-0500

Except that the initial issue description states "while dialing SIP extension" - not during a reload.  restart_monitor gets called anytime we do a Dial and create a SIP channel from the dialplan - so solving this for reloads won't solve it for everything.

In general, it sounds as if res_config_pgsql is making some assumptions it shouldn't be making.
By: Matt Jordan (mjordan) 2012-04-24 14:01:31.144-0500

I've acknowledged this issue.  Please keep in mind that res_config_pgsql is an extended support module, and response times may reflect that.  More information on module support states can be found here:

https://wiki.asterisk.org/wiki/display/AST/Asterisk+Module+Support+States
By: Sean Bright (seanbright) 2017-03-27 14:41:02.161-0500

A lot of the locking behavior was changed Asterisk 13.14 and 13.15 that most likely addressed this. If you are able to reproduce with 13.15 or newer, please feel free to re-open.