[asterisk-bugs] [JIRA] (ASTERISK-28469) AMI frozen on high load
Asterisk Team (JIRA)
noreply at issues.asterisk.org
Tue Jul 2 10:16:47 CDT 2019
[ https://issues.asterisk.org/jira/browse/ASTERISK-28469?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=247521#comment-247521 ]
Asterisk Team commented on ASTERISK-28469:
------------------------------------------
Thanks for creating a report! The issue has entered the triage process. That means the issue will wait in this status until a Bug Marshal has an opportunity to review the issue. Once the issue has been reviewed you will receive comments regarding the next steps towards resolution.
A good first step is for you to review the [Asterisk Issue Guidelines|https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines] if you haven't already. The guidelines detail what is expected from an Asterisk issue report.
Then, if you are submitting a patch, please review the [Patch Contribution Process|https://wiki.asterisk.org/wiki/display/AST/Patch+Contribution+Process].
Please note that once your issue enters an open state it has been accepted. As Asterisk is an open source project there is no guarantee or timeframe on when your issue will be looked into. If you need expedient resolution you will need to find and pay a suitable developer. Asking for an update on your issue will not yield any progress on it and will not result in a response. All updates are posted to the issue when they occur.
> AMI frozen on high load
> -----------------------
>
> Key: ASTERISK-28469
> URL: https://issues.asterisk.org/jira/browse/ASTERISK-28469
> Project: Asterisk
> Issue Type: Bug
> Security Level: None
> Components: Core/ManagerInterface
> Affects Versions: 16.4.0
> Environment: Linux deacsrtsk12 3.16.0-4-amd64 #1 SMP Debian 3.16.7-ckt25-2 (2016-04-08) x86_64 GNU/Linux
> Reporter: Stefan Repke
>
> The AMI queue gets stuck when running Asterisk 16.0.4 with ~30 calls per minute:
> After a few hundred calls have been processed, no further manager events are distrubuted and no new manager connections are accepted.
> The problem is reproducable and we've created a dump. I think the reason is that thread 0x7f6e6e56c700 is blocked in {{send_string}} of {{manager.c:3033}} (while holding/blocking lock 0x7f6ee0003260).
> Our version of libc6 is 2.19-18+deb8u10.
> The CLI command {{manager show eventq}} produces dozens of megabytes of output consisting of the queued events.
> {noformat:title=core show locks}
> =======================================================================
> === 16.4.0
> === Currently Held Locks
> =======================================================================
> ===
> === <pending> <lock#> (<file>): <lock type> <line num> <function> <lock name> <lock addr> (times locked)
> ===
> === Thread ID: 0x7f6e6ffff700 LWP:11439 (desc->accept_fn started at [ 770] tcptls.c ast_tcptls_server_start())
> === ---> Waiting for Lock #0 (manager.c): MUTEX 6896 purge_sessions session 0x7f6ee0003260 (1)
> [0x50277a] asterisk lock.h:446 ast_reentrancy_lock()
> [inlined] asterisk lock.c:272 __ast_pthread_mutex_lock()
> [0x45bd6d] asterisk astobj2.c:243 __ao2_lock()
> [0x5faaca] asterisk manager.c:2678 handle_showmanconn()
> [0x4bf2e5] asterisk cli.c:2834 ast_cli_command_full()
> [0x4bf454] asterisk cli.c:2861 ast_cli_command_multiple_full()
> [0x45865f] asterisk asterisk.c:1420 netconsole()
> [0x5a40c5] asterisk utils.c:1251 dummy_start()
> [0x7f6efd2c5064] libpthread.so.0 pthread_create.c:309 start_thread()
> [0x7f6efc26862d] libc.so.6 clone.S:113 clone()
> === --- ---> Locked Here: manager.c line 6104 (process_events)
> === -------------------------------------------------------------------
> ===
> === Thread ID: 0x7f6e6e56c700 LWP:11491 (handle_tcptls_connection started at [ 309] tcptls.c ast_tcptls_server_root())
> === ---> Lock #0 (manager.c): MUTEX 6104 process_events s->session 0x7f6ee0003260 (1)
> [0x50277a] asterisk lock.h:446 ast_reentrancy_lock()
> [inlined] asterisk lock.c:272 __ast_pthread_mutex_lock()
> [0x45bd6d] asterisk astobj2.c:243 __ao2_lock()
> [0x5fff11] asterisk manager.c:6105 process_events()
> [0x604be8] asterisk manager.c:6714 do_message()
> [inlined] asterisk manager.c:6853 session_do()
> [0x5a40c5] asterisk utils.c:1251 dummy_start()
> [0x7f6efd2c5064] libpthread.so.0 pthread_create.c:309 start_thread()
> [0x7f6efc26862d] libc.so.6 clone.S:113 clone()
> === -------------------------------------------------------------------
> ===
> === Thread ID: 0x7f6e6dc38700 LWP:23563 (netconsole started at [ 1529] asterisk.c listener())
> === ---> Waiting for Lock #0 (manager.c): MUTEX 2673 handle_showmanconn session 0x7f6ee0003260 (1)
> [0x50277a] asterisk lock.h:446 ast_reentrancy_lock()
> [inlined] asterisk lock.c:272 __ast_pthread_mutex_lock()
> [0x45bd6d] asterisk astobj2.c:243 __ao2_lock()
> [0x5faaca] asterisk manager.c:2678 handle_showmanconn()
> [0x4bf2e5] asterisk cli.c:2834 ast_cli_command_full()
> [0x4bf454] asterisk cli.c:2861 ast_cli_command_multiple_full()
> [0x45865f] asterisk asterisk.c:1420 netconsole()
> [0x5a40c5] asterisk utils.c:1251 dummy_start()
> [0x7f6efd2c5064] libpthread.so.0 pthread_create.c:309 start_thread()
> [0x7f6efc26862d] libc.so.6 clone.S:113 clone()
> === --- ---> Locked Here: manager.c line 6104 (process_events)
> === -------------------------------------------------------------------
> ===
> === Thread ID: 0x7f6e6d380700 LWP:23932 (netconsole started at [ 1529] asterisk.c listener())
> === ---> Waiting for Lock #0 (manager.c): MUTEX 2673 handle_showmanconn session 0x7f6ee0003260 (1)
> [0x50277a] asterisk lock.h:446 ast_reentrancy_lock()
> [inlined] asterisk lock.c:272 __ast_pthread_mutex_lock()
> [0x45bd6d] asterisk astobj2.c:243 __ao2_lock()
> [0x5faaca] asterisk manager.c:2678 handle_showmanconn()
> [0x4bf2e5] asterisk cli.c:2834 ast_cli_command_full()
> [0x4bf454] asterisk cli.c:2861 ast_cli_command_multiple_full()
> [0x45865f] asterisk asterisk.c:1420 netconsole()
> [0x5a40c5] asterisk utils.c:1251 dummy_start()
> [0x7f6efd2c5064] libpthread.so.0 pthread_create.c:309 start_thread()
> [0x7f6efc26862d] libc.so.6 clone.S:113 clone()
> === --- ---> Locked Here: manager.c line 6104 (process_events)
> === -------------------------------------------------------------------
> ===
> === Thread ID: 0x7f6e6d3fc700 LWP:24956 (netconsole started at [ 1529] asterisk.c listener())
> === ---> Waiting for Lock #0 (manager.c): MUTEX 2673 handle_showmanconn session 0x7f6ee0003260 (1)
> [0x50277a] asterisk lock.h:446 ast_reentrancy_lock()
> [inlined] asterisk lock.c:272 __ast_pthread_mutex_lock()
> [0x45bd6d] asterisk astobj2.c:243 __ao2_lock()
> [0x5faaca] asterisk manager.c:2678 handle_showmanconn()
> [0x4bf2e5] asterisk cli.c:2834 ast_cli_command_full()
> [0x4bf454] asterisk cli.c:2861 ast_cli_command_multiple_full()
> [0x45865f] asterisk asterisk.c:1420 netconsole()
> [0x5a40c5] asterisk utils.c:1251 dummy_start()
> [0x7f6efd2c5064] libpthread.so.0 pthread_create.c:309 start_thread()
> [0x7f6efc26862d] libc.so.6 clone.S:113 clone()
> === --- ---> Locked Here: manager.c line 6104 (process_events)
> === -------------------------------------------------------------------
> ===
> === Thread ID: 0x7f6efb470700 LWP:25271 (netconsole started at [ 1529] asterisk.c listener())
> === ---> Waiting for Lock #0 (manager.c): MUTEX 2673 handle_showmanconn session 0x7f6ee0003260 (1)
> [0x50277a] asterisk lock.h:446 ast_reentrancy_lock()
> [inlined] asterisk lock.c:272 __ast_pthread_mutex_lock()
> [0x45bd6d] asterisk astobj2.c:243 __ao2_lock()
> [0x5faaca] asterisk manager.c:2678 handle_showmanconn()
> [0x4bf2e5] asterisk cli.c:2834 ast_cli_command_full()
> [0x4bf454] asterisk cli.c:2861 ast_cli_command_multiple_full()
> [0x45865f] asterisk asterisk.c:1420 netconsole()
> [0x5a40c5] asterisk utils.c:1251 dummy_start()
> [0x7f6efd2c5064] libpthread.so.0 pthread_create.c:309 start_thread()
> [0x7f6efc26862d] libc.so.6 clone.S:113 clone()
> === --- ---> Locked Here: manager.c line 6104 (process_events)
> === -------------------------------------------------------------------
> ===
> =======================================================================
> {noformat}
> {noformat:title=brief.txt}
> ...
> Thread 52 (Thread 0x7f6e6e56c700 (LWP 11491)):
> #0 0x00007f6efc25faed in poll () at ../sysdeps/unix/syscall-template.S:81
> #1 0x00000000005a6b78 in poll (__timeout=<optimized out>, __nfds=1, __fds=0x7f6e6e56b2d0) at /usr/include/x86_64-linux-gnu/bits/poll2.h:46
> #2 ast_wait_for_output (fd=<optimized out>, ms=<optimized out>) at utils.c:1357
> #3 0x00000000004f6f89 in ast_iostream_write (stream=0x7f6e680041e0, buffer=0x7f6e7018e4f8, size=5000, size at entry=487) at iostream.c:473
> #4 0x00000000004f747d in ast_iostream_write (stream=stream at entry=0x7f6e680041e0, buffer=buffer at entry=0x7f6e7018e4f8, size=size at entry=487) at iostream.c:475
> #5 0x0000000000600121 in send_string (string=0x7f6e7018e4f8 "Event: NewextenrnPrivilege: dialplan,allrnTimestamp: 1561990424.176441rnSystemName: deacsrtsk12rnChannel: SIP/999253-000002c8rnChannelState: 4rnChannelStateDesc: RingrnCallerIDNum: 999253rnCallerIDNam"..., s=0x7f6e6e56b4d0) at manager.c:3033
> #6 process_events (s=0x7f6e6e56b4d0) at manager.c:6117
> #7 0x0000000000604be8 in do_message (s=<optimized out>) at manager.c:6714
> #8 session_do (data=0x7f6e6e56b2d0) at manager.c:6853
> #9 0x00000000005a40c5 in dummy_start (data=0x7f6e68003dc0) at utils.c:1249
> #10 0x00007f6efd2c5064 in start_thread (arg=0x7f6e6e56c700) at pthread_create.c:309
> #11 0x00007f6efc26862d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
> ...
> {noformat}
> {noformat:title=full.txt}
> ...
> Thread 52 (Thread 0x7f6e6e56c700 (LWP 11491)):
> #0 0x00007f6efc25faed in poll () at ../sysdeps/unix/syscall-template.S:81
> No locals.
> #1 0x00000000005a6b78 in poll (__timeout=<optimized out>, __nfds=1, __fds=0x7f6e6e56b2d0) at /usr/include/x86_64-linux-gnu/bits/poll2.h:46
> No locals.
> #2 ast_wait_for_output (fd=<optimized out>, ms=<optimized out>) at utils.c:1357
> pfd = {{fd = 22, events = 4, revents = 0}}
> #3 0x00000000004f6f89 in ast_iostream_write (stream=0x7f6e680041e0, buffer=0x7f6e7018e4f8, size=5000, size at entry=487) at iostream.c:473
> No locals.
> #4 0x00000000004f747d in ast_iostream_write (stream=stream at entry=0x7f6e680041e0, buffer=buffer at entry=0x7f6e7018e4f8, size=size at entry=487) at iostream.c:475
> No locals.
> #5 0x0000000000600121 in send_string (string=0x7f6e7018e4f8 "Event: NewextenrnPrivilege: dialplan,allrnTimestamp: 1561990424.176441rnSystemName: deacsrtsk12rnChannel: SIP/999253-000002c8rnChannelState: 4rnChannelStateDesc: RingrnCallerIDNum: 999253rnCallerIDNam"..., s=0x7f6e6e56b4d0) at manager.c:3033
> stream = 0x7f6e680041e0
> len = 487
> res = <optimized out>
> string = 0x7f6e7018e4f8 "Event: NewextenrnPrivilege: dialplan,allrnTimestamp: 1561990424.176441rnSystemName: deacsrtsk12rnChannel: SIP/999253-000002c8rnChannelState: 4rnChannelStateDesc: RingrnCallerIDNum: 999253rnCallerIDNam"...
> s = 0x7f6e6e56b4d0
> #6 process_events (s=0x7f6e6e56b4d0) at manager.c:6117
> eqe = <optimized out>
> ret = <optimized out>
> __PRETTY_FUNCTION__ = "process_events"
> #7 0x0000000000604be8 in do_message (s=<optimized out>) at manager.c:6714
> m = {hdrcount = 6, headers = {0x7f6ee0004620 "action: Monitor", 0x7f6ee04085d0 "actionid: 537#355425276_673410#", 0x7f6ee0008fb0 "file: /tmp/U23TJQ5V23X4MZQB", 0x7f6ee0009b70 "format: wav", 0x7f6ee0009b20 "channel: IAX2/999005-3957", 0x7f6ee0008fe0 "mix: true", 0x0 <repeats 122 times>}}
> header_buf = "mix: true000AX2/999005-3957000B000061060#", '000' <repeats 993 times>
> now = 1561988218
> #8 session_do (data=0x7f6e6e56b2d0) at manager.c:6853
> s = {session = 0x7f6ee00032b8, stream = 0x7f6e680041e0, tcptls_session = 0x7f6e68004068, parsing = MESSAGE_OKAY, write_error = -1, hook = 0x0, lock = {mutex = {__data = {__lock = 0, __count = 0, __owner = 0, __nusers = 0, __kind = 1, __spins = 0, __elision = 0, __list = {__prev = 0x0, __next = 0x0}}, __size = '000' <repeats 16 times>, "001", '000' <repeats 22 times>, __align = 0}, track = 0x7f6ee0005ee0, flags = {tracking = 1, setup = 1}}}
> res = 5
> arg = 1
> ser_remote_address_tmp = {ss = {ss_family = 10, __ss_align = 0, __ss_padding = "000000377377177000000001", '000' <repeats 48 times>, "|254367373n177000000000000000000000000000000370377377377377377377377220324367373n177000000340266Vnn177000000220I036377n177000000000000000000000000000"}, len = 28}
> __PRETTY_FUNCTION__ = "session_do"
> #9 0x00000000005a40c5 in dummy_start (data=0x7f6e68003dc0) at utils.c:1249
> __cancel_buf = {__cancel_jmp_buf = {{__cancel_jmp_buf = {140114181235520, 57934947619282876, 140112167979552, 140114047020320, 21, 140112274310912, 57947742297497532, -139326592165109828}, __mask_was_saved = 0}}, __pad = {0x7f6e6e56bef0, 0x0, 0x7f6efc521878 <__elf_set___libc_thread_subfreeres_element___rpc_thread_destroy__>, 0x7f6efc521880 <internal_trans_names>}}
> __cancel_arg = 0x7f6e6e56c700
> __not_first_call = <optimized out>
> ret = <optimized out>
> a = {start_routine = 0x5955b0 <handle_tcptls_connection>, data = 0x7f6e68004068, name = 0x7f6e68004a20 "handle_tcptls_connection started at [ 309] tcptls.c ast_tcptls_server_root()"}
> mutex_attr = {__size = "001000000", __align = 1}
> __PRETTY_FUNCTION__ = "dummy_start"
> #10 0x00007f6efd2c5064 in start_thread (arg=0x7f6e6e56c700) at pthread_create.c:309
> __res = <optimized out>
> pd = 0x7f6e6e56c700
> now = <optimized out>
> unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140112274310912, -139326233515286596, 0, 140114047020320, 21, 140112274310912, 57947742289108924, 57695635703832508}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
> not_first_call = <optimized out>
> pagesize_m1 = <optimized out>
> sp = <optimized out>
> freesize = <optimized out>
> __PRETTY_FUNCTION__ = "start_thread"
> #11 0x00007f6efc26862d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
> No locals.
> ...
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.2#6252)
More information about the asterisk-bugs
mailing list