Exceptionally long voice queue

Asterisk Asterisk Support
1

Hi, this issue may be regarded as a continuation of Exceptionally long voice queue length help. I managed to build asterisk in debug mode with all necessary flags turned on, then I initiated call, waited until warning pops up again and typed core show locks into asterisk console,
which resulted in

=== ---> Lock #0 (sorcery.c): RDLOCK 1873 ast_sorcery_retrieve_by_id2 & (&object_type->wizards)->lock 0x5625fe6629e8 (1)
	/usr/local/sbin/asterisk(__ast_rwlock_rdlock+0xd0) [0x5625fd40e251]
	/usr/local/sbin/asterisk(ast_sorcery_retrieve_by_id2+0xec) [0x5625fd49ac89]
	/usr/local/sbin/asterisk(ast_sorcery_retrieve_by_id+0x2d) [0x5625fd49aed5]
	/usr/local/sbin/asterisk(ast_bucket_file_retrieve+0x3d) [0x5625fd37a35a]
	/usr/local/sbin/asterisk(ast_media_cache_retrieve+0x31d) [0x5625fd417638]
	/usr/local/sbin/asterisk(+0x1184e4) [0x5625fd3e74e4]
	/usr/local/sbin/asterisk(+0x11870e) [0x5625fd3e770e]
	/usr/local/sbin/asterisk(ast_openstream_full+0x125) [0x5625fd3e797d]
	/usr/local/sbin/asterisk(ast_openstream+0x2d) [0x5625fd3e7856]
	/usr/local/sbin/asterisk(ast_streamfile+0x45) [0x5625fd3e9046]
	/usr/local/lib/asterisk/modules/app_playback.so(+0x3018) [0x7fbc273dc018]
	/usr/local/sbin/asterisk(pbx_exec+0x125) [0x5625fd446111]
	/usr/local/sbin/asterisk(+0x1606c8) [0x5625fd42f6c8]
	/usr/local/sbin/asterisk(ast_spawn_extension+0x50) [0x5625fd433bd5]
	/usr/local/sbin/asterisk(+0x165989) [0x5625fd434989]
	/usr/local/sbin/asterisk(ast_pbx_run_args+0x9f) [0x5625fd436512]
	/usr/local/sbin/asterisk(ast_pbx_run+0x1d) [0x5625fd436550]
	/usr/local/lib/asterisk/modules/res_ari_channels.so(+0xc3e0) [0x7fbbdc0113e0]
	/usr/local/sbin/asterisk(+0x213912) [0x5625fd4e2912]
	/lib/x86_64-linux-gnu/libpthread.so.0(+0x76db) [0x7fbc4811a6db]
	/lib/x86_64-linux-gnu/libc.so.6(clone+0x3f) [0x7fbc4765461f]
=== ---> Lock #1 (bucket.c): RDLOCK 206 bucket_file_wizard_retrieve ((schemes)) 0x5625fe65a680 (1)
	/usr/local/sbin/asterisk(__ast_rwlock_rdlock+0xd0) [0x5625fd40e251]
	/usr/local/sbin/asterisk(__ao2_lock+0x192) [0x5625fd34307b]
	/usr/local/sbin/asterisk(+0x76a0d) [0x5625fd345a0d]
	/usr/local/sbin/asterisk(__ao2_callback+0x4f) [0x5625fd345da2]
	/usr/local/sbin/asterisk(__ao2_find+0x5f) [0x5625fd345e5a]
	/usr/local/sbin/asterisk(ast_bucket_file_alloc+0x133) [0x5625fd3799a4]
	/usr/local/lib/asterisk/modules/res_http_media_cache.so(+0x2d8d) [0x7fbbe2a65d8d]
	/usr/local/sbin/asterisk(+0xa8ee3) [0x5625fd377ee3]
	/usr/local/sbin/asterisk(ast_sorcery_retrieve_by_id2+0x1b9) [0x5625fd49ad56]
	/usr/local/sbin/asterisk(ast_sorcery_retrieve_by_id+0x2d) [0x5625fd49aed5]
	/usr/local/sbin/asterisk(ast_bucket_file_retrieve+0x3d) [0x5625fd37a35a]
	/usr/local/sbin/asterisk(ast_media_cache_retrieve+0x31d) [0x5625fd417638]
	/usr/local/sbin/asterisk(+0x1184e4) [0x5625fd3e74e4]
	/usr/local/sbin/asterisk(+0x11870e) [0x5625fd3e770e]
	/usr/local/sbin/asterisk(ast_openstream_full+0x125) [0x5625fd3e797d]
	/usr/local/sbin/asterisk(ast_openstream+0x2d) [0x5625fd3e7856]
	/usr/local/sbin/asterisk(ast_streamfile+0x45) [0x5625fd3e9046]
	/usr/local/lib/asterisk/modules/app_playback.so(+0x3018) [0x7fbc273dc018]
	/usr/local/sbin/asterisk(pbx_exec+0x125) [0x5625fd446111]
	/usr/local/sbin/asterisk(+0x1606c8) [0x5625fd42f6c8]
	/usr/local/sbin/asterisk(ast_spawn_extension+0x50) [0x5625fd433bd5]
	/usr/local/sbin/asterisk(+0x165989) [0x5625fd434989]
	/usr/local/sbin/asterisk(ast_pbx_run_args+0x9f) [0x5625fd436512]
	/usr/local/sbin/asterisk(ast_pbx_run+0x1d) [0x5625fd436550]
	/usr/local/lib/asterisk/modules/res_ari_channels.so(+0xc3e0) [0x7fbbdc0113e0]
	/usr/local/sbin/asterisk(+0x213912) [0x5625fd4e2912]
	/lib/x86_64-linux-gnu/libpthread.so.0(+0x76db) [0x7fbc4811a6db]
	/lib/x86_64-linux-gnu/libc.so.6(clone+0x3f) [0x7fbc4765461f]

To make things more clear for you, I want to point out that such warning occurs should the file be downloaded from remote server. I couldn’t reproduce it using local sound files.
Based on logs presented above, I may draw conclusion that two threads - one responsible for downloading a remote file, the other for pulling sound data from cache - hold one rdlock, and one of this two guys does its job slowly. So, how can I resolve this issue given all this?

UPD
I also get this

=== ---> Lock #0 (media_cache.c): MUTEX 167 ast_media_cache_retrieve media_cache 0x5625fdc47f70 (1)
	/usr/local/sbin/asterisk(__ast_pthread_mutex_lock+0xd0) [0x5625fd40c206]
	/usr/local/sbin/asterisk(__ao2_lock+0x10b) [0x5625fd342ff4]
	/usr/local/sbin/asterisk(ast_media_cache_retrieve+0x70) [0x5625fd41738b]
	/usr/local/sbin/asterisk(+0x1184e4) [0x5625fd3e74e4]
	/usr/local/sbin/asterisk(+0x11870e) [0x5625fd3e770e]
	/usr/local/sbin/asterisk(ast_openstream_full+0x125) [0x5625fd3e797d]
	/usr/local/sbin/asterisk(ast_openstream+0x2d) [0x5625fd3e7856]
	/usr/local/sbin/asterisk(ast_streamfile+0x45) [0x5625fd3e9046]
	/usr/local/lib/asterisk/modules/app_playback.so(+0x3018) [0x7fbc273dc018]
	/usr/local/sbin/asterisk(pbx_exec+0x125) [0x5625fd446111]
	/usr/local/sbin/asterisk(+0x1606c8) [0x5625fd42f6c8]
	/usr/local/sbin/asterisk(ast_spawn_extension+0x50) [0x5625fd433bd5]
	/usr/local/sbin/asterisk(+0x165989) [0x5625fd434989]
	/usr/local/sbin/asterisk(ast_pbx_run_args+0x9f) [0x5625fd436512]
	/usr/local/sbin/asterisk(ast_pbx_run+0x1d) [0x5625fd436550]
	/usr/local/lib/asterisk/modules/res_ari_channels.so(+0xc3e0) [0x7fbbdc0113e0]
	/usr/local/sbin/asterisk(+0x213912) [0x5625fd4e2912]
	/lib/x86_64-linux-gnu/libpthread.so.0(+0x76db) [0x7fbc4811a6db]
	/lib/x86_64-linux-gnu/libc.so.6(clone+0x3f) [0x7fbc4765461f]
=== ---> Lock #1 (sorcery.c): RDLOCK 2365 ast_sorcery_is_stale &(&object_type->wizards)->lock 0x5625fe6629e8 (1)
	/usr/local/sbin/asterisk(__ast_rwlock_rdlock+0xd0) [0x5625fd40e251]
	/usr/local/sbin/asterisk(ast_sorcery_is_stale+0xb9) [0x5625fd49c948]
	/usr/local/sbin/asterisk(ast_bucket_file_is_stale+0x22) [0x5625fd37a37e]
	/usr/local/sbin/asterisk(ast_media_cache_retrieve+0x141) [0x5625fd41745c]
	/usr/local/sbin/asterisk(+0x1184e4) [0x5625fd3e74e4]
	/usr/local/sbin/asterisk(+0x11870e) [0x5625fd3e770e]
	/usr/local/sbin/asterisk(ast_openstream_full+0x125) [0x5625fd3e797d]
	/usr/local/sbin/asterisk(ast_openstream+0x2d) [0x5625fd3e7856]
	/usr/local/sbin/asterisk(ast_streamfile+0x45) [0x5625fd3e9046]
	/usr/local/lib/asterisk/modules/app_playback.so(+0x3018) [0x7fbc273dc018]
	/usr/local/sbin/asterisk(pbx_exec+0x125) [0x5625fd446111]
	/usr/local/sbin/asterisk(+0x1606c8) [0x5625fd42f6c8]
	/usr/local/sbin/asterisk(ast_spawn_extension+0x50) [0x5625fd433bd5]
	/usr/local/sbin/asterisk(+0x165989) [0x5625fd434989]
	/usr/local/sbin/asterisk(ast_pbx_run_args+0x9f) [0x5625fd436512]
	/usr/local/sbin/asterisk(ast_pbx_run+0x1d) [0x5625fd436550]
	/usr/local/lib/asterisk/modules/res_ari_channels.so(+0xc3e0) [0x7fbbdc0113e0]
	/usr/local/sbin/asterisk(+0x213912) [0x5625fd4e2912]
	/lib/x86_64-linux-gnu/libpthread.so.0(+0x76db) [0x7fbc4811a6db]
	/lib/x86_64-linux-gnu/libc.so.6(clone+0x3f) [0x7fbc4765461f]
2

as you are using a version of asterisk that is EOL, i’ll recommend you upgrade to asterisk 18 as it should be able to use the same config
and then retest

3

question which version are you using ?

4

I’m using version 20.1.0

5

lol, as you were referring to a thread where they were using 13 I assumed you where two
well I was wrong :-/

6

@jcolp could you please point me in the right direction? I see that somehow ast_media_cache_retrieve is called twice in context of a single thread. I really need to solve this problem.

7

If I have anything of value to add to threads then I post. Tagging me doesn’t help.

The backtrace shows where things are blocked, including functions, you then have to look at the code, determine precisely what is going on, and how to fix it.

8

Okay, got you

9

Now I see that curl is a potential bottleneck. The only thing I don’t understand yet is why curl downloads the same file over and over again, isn’t file data supposed to be cached for later use?

10

Seems like I found the solution to the problem. First of all, such a slow file download is a result of dns lags during resolving, but I was wondering why it keeps downloading file every single time and learned that caching ttl for remote files is determined by value of a max-age in http request headers. I modified a source code a bit and this problem just went away.