[asterisk-bugs] [JIRA] (ASTERISK-26551) Voicemail deadlock when under load with ODBC backend

Wed Nov 9 08:10:10 CST 2016

    [ https://issues.asterisk.org/jira/browse/ASTERISK-26551?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=233526#comment-233526 ] 

Joshua Colp commented on ASTERISK-26551:
----------------------------------------

Seems to be:

{code}
Thread 198 (Thread 0x7fb41b2be700 (LWP 13868)):
#0  0x00007fb4c49afddb in __libc_recv (fd=43, buf=0x7fb43cd6bd10, n=16384, flags=-1) at ../sysdeps/unix/sysv/linux/x86_64/recv.c:33
#1  0x00007fb46045da8d in inline_mysql_socket_recv (flags=<optimized out>, n=<optimized out>, buf=<optimized out>, mysql_socket=..., src_line=<optimized out>, src_file=<optimized out>) at /export/home/pb2/build/sb_0-17781605-1454370718.35/mysql-5.7.11/include/mysql/psi/mysql_socket.h:823
#2  vio_read (vio=0x7fb43c062780, buf=<optimized out>, size=<optimized out>) at /export/home/pb2/build/sb_0-17781605-1454370718.35/mysql-5.7.11/vio/viosocket.c:123
#3  0x00007fb46045db12 in vio_read_buff (vio=0x2b, buf=0x7fb41630c030 "\001", size=4) at /export/home/pb2/build/sb_0-17781605-1454370718.35/mysql-5.7.11/vio/viosocket.c:166
#4  0x00007fb4604b8333 in net_read_raw_loop (count=4, net=<optimized out>) at /export/home/pb2/build/sb_0-17781605-1454370718.35/mysql-5.7.11/sql/net_serv.cc:665
#5  net_read_packet_header (net=<optimized out>) at /export/home/pb2/build/sb_0-17781605-1454370718.35/mysql-5.7.11/sql/net_serv.cc:755
#6  net_read_packet (net=0x7fb43c8fc8d8, complen=0x7fb41b2ac0c8) at /export/home/pb2/build/sb_0-17781605-1454370718.35/mysql-5.7.11/sql/net_serv.cc:815
#7  0x00007fb4604b869c in my_net_read (net=0x2b) at /export/home/pb2/build/sb_0-17781605-1454370718.35/mysql-5.7.11/sql/net_serv.cc:892
#8  0x00007fb46044a6bb in cli_safe_read_with_ok (mysql=0x7fb43c8fc8d8, parse_ok=1 '\001', is_data_packet=0x0) at /export/home/pb2/build/sb_0-17781605-1454370718.35/mysql-5.7.11/sql-common/client.c:1035
#9  0x00007fb46044f11c in cli_advanced_command (mysql=0x7fb43c8fc8d8, command=<optimized out>, header=<optimized out>, header_length=0, arg=<optimized out>, arg_length=0, skip_check=0 '\000', stmt=0x0) at /export/home/pb2/build/sb_0-17781605-1454370718.35/mysql-5.7.11/sql-common/client.c:1316
#10 0x00007fb460440506 in mysql_ping (mysql=0x2b, mysql at entry=0x7fb43c8fc8d8) at /export/home/pb2/build/sb_0-17781605-1454370718.35/mysql-5.7.11/libmysql/libmysql.c:935
#11 0x00007fb46042fe86 in MySQLGetConnectAttr (hdbc=hdbc at entry=0x7fb43c8fc8d0, attrib=1209, char_attr=char_attr at entry=0x7fb41b2ac2c8, num_attr=num_attr at entry=0x7fb41b2ac480) at /export/home/pb2/build/sb_0-18248528-1457730093.52/mysql-connector-odbc-5.3.6-src/driver/options.c:486
#12 0x00007fb46043dc9d in SQLGetConnectAttrImpl (hdbc=0x7fb43c8fc8d0, attribute=<optimized out>, value=0x7fb41b2ac480, value_max=0, value_len=0x0) at /export/home/pb2/build/sb_0-18248528-1457730093.52/mysql-connector-odbc-5.3.6-src/driver/ansi.c:584
#13 0x00007fb46043dd8b in SQLGetConnectAttr (hdbc=<optimized out>, attribute=<optimized out>, value=<optimized out>, value_max=<optimized out>, value_len=<optimized out>) at /export/home/pb2/build/sb_0-18248528-1457730093.52/mysql-connector-odbc-5.3.6-src/driver/ansi.c:567
#14 0x00007fb4621016f2 in SQLGetConnectAttr (connection_handle=0x2b, attribute=1020706064, value=0x4000, buffer_length=-1, string_length=0x0) at SQLGetConnectAttr.c:742
#15 0x00007fb462357c6d in connection_dead (connection=0x7fb43cb04df8, class=0x38b1478) at res_odbc.c:778
#16 0x00007fb462358087 in _ast_odbc_request_obj2 (name=0x7fb43389f200 <odbc_database> "asterisk2", flags=..., file=0x7fb43369340b "app_voicemail.c", function=0x7fb43369a672 <__PRETTY_FUNCTION__.18641> "messagecount", lineno=5817) at res_odbc.c:851
#17 0x00007fb462358294 in _ast_odbc_request_obj (name=0x7fb43389f200 <odbc_database> "asterisk2", check=0, file=0x7fb43369340b "app_voicemail.c", function=0x7fb43369a672 <__PRETTY_FUNCTION__.18641> "messagecount", lineno=5817) at res_odbc.c:882
#18 0x00007fb43367215e in messagecount (mailbox_id=0x7fb41b2ad630 "80283 at DMOORETEST", folder=0x7fb433693d00 "INBOX") at app_voicemail.c:5817
#19 0x00007fb433672469 in has_voicemail (mailboxes=0x7fb41b2ad750 "80283 at DMOORETEST", folder=0x0) at app_voicemail.c:5867
#20 0x000000000043e4c5 in ast_app_has_voicemail (mailboxes=0x7fb41b2ad750 "80283 at DMOORETEST", folder=0x0) at app.c:707
#21 0x00007fb433679658 in notify_new_message (chan=0x7fb43c23e638, vmu=0x7fb41b2b2a10, vms=0x0, msgnum=0, duration=97, fmt=0x7fb41b2ad6d0 "wav", cidnum=0x7fb43c90c9f0 "+14194389010", cidname=0x7fb43c230bd0 "4194389010", flag=0x7fb41b2b29c0 "") at app_voicemail.c:8073
#22 0x00007fb43367619f in leave_voicemail (chan=0x7fb43c23e638, ext=0x7fb43c84d098 "80283", options=0x7fb41b2bb4e0) at app_voicemail.c:6995
#23 0x00007fb43368685c in vm_exec (chan=0x7fb43c23e638, data=0x7fb41b2bb630 "80283 at DMOORETEST,u") at app_voicemail.c:12086
#24 0x000000000057fab8 in pbx_exec (c=0x7fb43c23e638, app=0x4d72190, data=0x7fb41b2bb630 "80283 at DMOORETEST,u") at pbx_app.c:485
#25 0x000000000056da04 in pbx_extension_helper (c=0x7fb43c23e638, con=0x0, context=0x7fb43c23eff0 "VoiceMail", exten=0x7fb43c23f040 "80283", priority=3, label=0x0, callerid=0x7fb43c90c9f0 "+14194389010", action=E_SPAWN, found=0x7fb41b2bdcd4, combined_find_spawn=1) at pbx.c:2834
#26 0x0000000000570e3d in ast_spawn_extension (c=0x7fb43c23e638, context=0x7fb43c23eff0 "VoiceMail", exten=0x7fb43c23f040 "80283", priority=3, callerid=0x7fb43c90c9f0 "+14194389010", found=0x7fb41b2bdcd4, combined_find_spawn=1) at pbx.c:4060
#27 0x0000000000571aa4 in __ast_pbx_run (c=0x7fb43c23e638, args=0x0) at pbx.c:4235
#28 0x00000000005731df in pbx_thread (data=0x7fb43c23e638) at pbx.c:4555
#29 0x00000000005f54a1 in dummy_start (data=0x7fb43dc65c10) at utils.c:1235
#30 0x00007fb4c49a90a4 in start_thread (arg=0x7fb41b2be700) at pthread_create.c:309
#31 0x00007fb4c395b62d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
{code}

It's blocked waiting on a response from the MySQL server. Since you've updated to the latest UnixODBC you can also use multiple connections, which may help. It's done using the "max_connections" option in res_odbc.conf

> Voicemail deadlock when under load with ODBC backend
> ----------------------------------------------------
>
>                 Key: ASTERISK-26551
>                 URL: https://issues.asterisk.org/jira/browse/ASTERISK-26551
>             Project: Asterisk
>          Issue Type: Bug
>      Security Level: None
>          Components: Applications/app_voicemail, Applications/app_voicemail/ODBC
>    Affects Versions: 13.11.2
>         Environment: Up to date Debian 8
> chan_pjsip
> Cloned a production server and enabled debug then setup automated tests to keep the voicemail system under load in order to reproduce this bug.
>            Reporter: David Moore
>            Assignee: Unassigned
>         Attachments: 2016-11-09-00_27_31-backtrace, 2016-11-09-00_27_31-channels, 2016-11-09-00_27_31-debug, 2016-11-09-00_27_31-locks, backtrace-threads10.txt, core-show-locks10.txt, dialplan.txt, odbc_show_all.txt
>
>
> Voicemail-only server (answering incoming calls from peer with chan_pjsip)
> Bug can be reproduced by placing the voicemail system under load, I did this by leaving many simultaneous voicemails through automated means. After running for several hours the voicemail app locks up. The system will still accept incoming calls, and enter the Voicemail app, but no audio is returned and the call does not progress further.
> The system eventually recovers and resumes normal operation, this generally takes between 3 and 20 minutes.
> I took ten backtraces and ten copies of 'core show locks' during this deadlock on my debug server, I can upload all of them if necessary, I will begin by attaching the latest data set and will upload more upon request to avoid cluttering things up unnecessarily

--
This message was sent by Atlassian JIRA
(v6.2#6252)