Exceptionally long voice > queue length queuing

Hi,
Recently in the last few days my Asterisk system has completely gone to you-know-what.

I am getting tons of these when watching ‘asterisk -rv’

[Apr 20 21:39:15] WARNING[24491][C-00000197]: channel.c:1162 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/s@announce-0000015b;1

When this happens the system will not accept any more calls and in order to make it work again, I have to completely restart. I was only 14.2 until a few minutes ago when I upgraded to 14.4 so I’m hoping that will help but I’m betting it won’t.

Any help would be greatly appreciated.

edit: 14.4 update did not help.

This occurs when the underlying thread that is supposed to read the voice frames is either deadlocked so it can’t do anything, or goes away without properly destroying the channel. Both of these shouldn’t happen. I’d suggest filing an issue[1] and attaching a deadlock backtrace[2] with your console log and a description of your usage/scenario.

[1] https://issues.asterisk.org/jira
[2] https://wiki.asterisk.org/wiki/display/AST/Getting+a+Backtrace#GettingaBacktrace-GettingInformationForADeadlock

Thanks… I am currently working towards your suggestion.

Reporting further findings it appears this completely revolves around Local & CBAnn Channels:

Exceptionally long voice queue length queuing to CBAnn/17-00008b7f;1
Exceptionally long voice queue length queuing to CBAnn/18-00001860;1
Exceptionally long voice queue length queuing to CBAnn/18-0000891d;1
Exceptionally long voice queue length queuing to CBAnn/19-00008531;1
Exceptionally long voice queue length queuing to Local/s@announce-0000003f;1
Exceptionally long voice queue length queuing to Local/s@announce-00000048;1
Exceptionally long voice queue length queuing to Local/s@announce-0000004a;1
Exceptionally long voice queue length queuing to Local/s@announce-0000015b;1
Exceptionally long voice queue length queuing to Local/s@announce-00000c06;1
Exceptionally long voice queue length queuing to Local/s@announce-00000c08;1
Exceptionally long voice queue length queuing to Local/s@announce-00000c09;1
Exceptionally long voice queue length queuing to Local/s@announce-00000c0a;1
Exceptionally long voice queue length queuing to Local/s@announce-00000c53;1
Exceptionally long voice queue length queuing to Local/s@announce-00000c54;1
Exceptionally long voice queue length queuing to Local/s@announce-00000c55;1
Exceptionally long voice queue length queuing to Local/s@announce-00000c56;1
Exceptionally long voice queue length queuing to Local/s@announce-0000186d;1
Exceptionally long voice queue length queuing to Local/s@announce-00005e5c;1
Exceptionally long voice queue length queuing to Local/s@announce-00005e5d;1
Exceptionally long voice queue length queuing to Local/s@announce-00005e5e;1
Exceptionally long voice queue length queuing to Local/s@announce-00005e5f;1
Exceptionally long voice queue length queuing to Local/s@announce-00005e60;1
Exceptionally long voice queue length queuing to Local/s@announce-00005e61;1
Exceptionally long voice queue length queuing to Local/s@announce-00005e62;1
Exceptionally long voice queue length queuing to Local/s@announce-00009176;1
Exceptionally long voice queue length queuing to Local/s@announce-00009177;1
Exceptionally long voice queue length queuing to Local/s@announce-00009178;1
Exceptionally long voice queue length queuing to Local/s@announce-00009179;1
Exceptionally long voice queue length queuing to Local/s@announce-0000917c;1
Exceptionally long voice queue length queuing to Local/s@announce-0000917e;1
Exceptionally long voice queue length queuing to Local/s@announce-0000917f;1
Exceptionally long voice queue length queuing to Local/s@playchan-0000004c;2
Exceptionally long voice queue length queuing to Local/s@playchan-00000c51;1
Exceptionally long voice queue length queuing to Local/s@playchan-00000c52;1
Exceptionally long voice queue length queuing to Local/s@playchan-00000c57;2
Exceptionally long voice queue length queuing to Local/s@playchan-0000186e;2

and noticed this from a few years ago (probably not related)…

2014-05-07 20:59 +0000 [r413453-413455] Richard Mudgett rmudgett@digium.com

  • apps/app_confbridge.c, /: app_confbridge: Fixed “CBAnn” channels
    not going away. Fixed a ref leak in conf_handle_talker_cb()
    everytime the conference bridge was found to report a channel’s
    talker status change. The resulting leak caused the "CBAnn"
    channels and the conference bridge to never be destroyed. Thanks
    to Richard Kenner on the asterisk-user’s list for locating the
    problem. Reported by: Richard Kenner … Merged revisions
    413454 from http://svn.asterisk.org/svn/asterisk/branches/12

No matter what I do or what I try, I can not get menuselect to work. It says I need ncurses. Ive installed everything related to ncurses I can possible find but it just won’t work.

How can I accomplish this without menuselect:

In the Compiler Flags menu of menuselect and you should enable DEBUG_THREADS, DONT_OPTIMIZE and BETTER_BACKTRACES. Then, you need to recompile, re-install, and restart Asterisk before following the steps below.

The following can be used to enable those from the command line:

menuselect/menuselect --enable DEBUG_THREADS --enable DONT_OPTIMIZE --enable BETTER_BACKTRACES menuselect.makeopts

1 Like

Thanks that worked, one more question:

Do I want to run in interactive mode: gdb asterisk or do I want to wait for my problem to occur and then do:

  • gdb -ex “thread apply all bt” --batch /usr/sbin/asterisk pidof asterisk > /tmp/backtrace-threads.txt
  • asterisk -rx “core show locks” > /tmp/core-show-locks.txt

In other words if I’m not actively watching at the time the problem occurs will the above commands be useful?

You would want to attach gdb at the time it happens and get the information.

1 Like

Another thing I just noticed since my problem started Asterisk seems to be generating a lot of /tmp/ast-ami-xxxxx files, which are all 0 bytes except for 1 which seems to be active. They go back around 4 days (when the problem first started occurring).

Is there a global variable limit?

So when I do:

menuselect/menuselect --enable DEBUG_THREADS --enable DONT_OPTIMIZE --enable BETTER_BACKTRACES menuselect.makeopts

It dramatically limits the number of global variables I can set. No idea why. I set approx 7K globals when I start up but with the above it seems to die at around ~700.

You can try not enabling DEBUG_THREADS.

1 Like

That worked in allowing me to set all my globals but now:

asterisk -rx "core show locks"
No such command 'core show locks' (type 'core show help core show locks' for other possible commands)

This DOES work though

gdb -ex "thread apply all bt" --batch /usr/sbin/asteriskpidof asterisk> /tmp/backtrace-threads.txt

Man this is stressful… I wish it were one little part I could shut off but this problem completely kills my whole system.

From the backtrace, no idea if this has any value

Tons of these:
    [New LWP 8479]
    [New LWP 8478]
    [New LWP 8477]
    [New LWP 8476]
    [New LWP 8475]
    [New LWP 8474]
    [New LWP 8473]
    [New LWP 8472]
    [New LWP 8471]
    [New LWP 8470]
    [New LWP 8467]
    [New LWP 8463]
    [New LWP 8462]
    [New LWP 8461]
    [Thread debugging using libthread_db enabled]
    Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
    0x00007f21cc3cfaed in poll () at ../sysdeps/unix/syscall-template.S:81

    Thread 239 (Thread 0x7f21cedf1700 (LWP 8461)):
    #0  pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
    #1  0x00000000005457ef in __ast_cond_wait (filename=0x653d80 "db.c", lineno=968, func=0x654e72 <__PRETTY_FUNCTION__.16179> "db_sync_thread", cond_name=0x654d33 "&dbcond", mutex_name=0x654059 "&dblock", cond=0x8fe5a0 <dbcond>, t=0x8dfa40 <dblock>) at lock.c:600
    #2  0x00000000004fe63b in db_sync_thread (data=0x0) at db.c:968
    #3  0x000000000060efa7 in dummy_start (data=0x2561a10) at utils.c:1230
    #4  0x00007f21cd0f0064 in start_thread (arg=0x7f21cedf1700) at pthread_create.c:309
    #5  0x00007f21cc3d862d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

    These repeat some:

    Thread 238 (Thread 0x7f21ced75700 (LWP 8462)):
    #0  sem_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/sem_wait.S:85
    #1  0x00000000005f7b9c in ast_sem_wait (sem=0x2e5e8a0) at /opt/sipx/etc/asterisk-14.4.0/include/asterisk/sem.h:61
    #2  0x00000000005f7c5d in default_tps_processing_function (data=0x2e5e928) at taskprocessor.c:178
    #3  0x000000000060efa7 in dummy_start (data=0x2e5eab0) at utils.c:1230
    #4  0x00007f21cd0f0064 in start_thread (arg=0x7f21ced75700) at pthread_create.c:309
    #5  0x00007f21cc3d862d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111


    then:

    Thread 231 (Thread 0x7f21cb7c3700 (LWP 8474)):
        #0  __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
        #1  0x00007f21cd0f2494 in _L_lock_952 () from /lib/x86_64-linux-gnu/libpthread.so.0
        #2  0x00007f21cd0f22f6 in __GI___pthread_mutex_lock (mutex=0x7f212c11d400) at ../nptl/pthread_mutex_lock.c:114
        #3  0x00000000005456a8 in __ast_pthread_mutex_lock (filename=0x644b00 "channel.c", lineno=1333, func=0x64a310 <__PRETTY_FUNCTION__.18737> "ast_channel_by_name_cb", mutex_name=0x645d98 "chan", t=0x7f212c11d400) at lock.c:315
        #4  0x000000000045da85 in __ao2_lock (user_data=0x7f212c11d458, lock_how=AO2_LOCK_REQ_MUTEX, file=0x644b00 "channel.c", func=0x64a310 <__PRETTY_FUNCTION__.18737> "ast_channel_by_name_cb", line=1333, var=0x645d98 "chan") at astobj2.c:211
        #5  0x00000000004b2c3c in ast_channel_by_name_cb (obj=0x7f212c11d458, arg=0x7f21cb7c2ca0, data=0x7f21cb7c2c60, flags=0) at channel.c:1333
        #6  0x0000000000460325 in internal_ao2_traverse (self=0x315a368, flags=OBJ_SEARCH_NONE, cb_fn=0x4b2b9e <ast_channel_by_name_cb>, arg=0x7f21cb7c2ca0, data=0x7f21cb7c2c60, type=AO2_CALLBACK_WITH_DATA, tag=0x644b4d "", file=0x644b00 "channel.c", line=1318, func=0x64a2f0 <__PRETTY_FUNCTION__.18726> "ast_channel_callback") at astobj2_container.c:328
        #7  0x000000000046063f in __ao2_callback_data (c=0x315a368, flags=OBJ_SEARCH_NONE, cb_fn=0x4b2b9e <ast_channel_by_name_cb>, arg=0x7f21cb7c2ca0, data=0x7f21cb7c2c60, tag=0x644b4d "", file=0x644b00 "channel.c", line=1318, func=0x64a2f0 <__PRETTY_FUNCTION__.18726> "ast_channel_callback") at astobj2_container.c:423
        #8  0x00000000004b2b98 in ast_channel_callback (cb_fn=0x4b2b9e <ast_channel_by_name_cb>, arg=0x7f21cb7c2ca0, data=0x7f21cb7c2c60, ao2_flags=0) at channel.c:1318
        #9  0x00000000004b3207 in ast_channel_get_by_name_prefix (name=0x7f21cb7c2ca0 "CBAnn/9-", name_len=8) at channel.c:1476
        #10 0x00000000004feb46 in ast_parse_device_state (device=0x42c5a4c "CBAnn/9") at devicestate.c:303
        #11 0x00000000004fee67 in _ast_device_state (device=0x42c5a4c "CBAnn/9", check_cache=0) at devicestate.c:379
        #12 0x00000000004ff2bb in do_state_change (device=0x42c5a4c "CBAnn/9", cachable=AST_DEVSTATE_NOT_CACHABLE) at devicestate.c:472
        #13 0x00000000004ff72e in do_devstate_changes (data=0x0) at devicestate.c:564
        #14 0x000000000060efa7 in dummy_start (data=0x316abc0) at utils.c:1230
        #15 0x00007f21cd0f0064 in start_thread (arg=0x7f21cb7c3700) at pthread_create.c:309
        #16 0x00007f21cc3d862d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

The complete backtrace is needed. With what you have provided a channel is deadlocked causing a cascade of other threads to also block on it.

Here is the whole backtrace: 3000+ lines

I’d suggest filing an issue on the issue tracker[1] with the information I previously mentioned.

[1] https://issues.asterisk.org/jira

Thanks! I did that. Hopefully it’ll help.

https://issues.asterisk.org/jira/browse/ASTERISK-26956