[Home]

Summary:ASTERISK-19763: Confbridge with SIP to Local channel results in hung video; Exceptionally long queue length queuing to Bridge
Reporter:tootai (tootai)Labels:
Date Opened:2012-04-20 06:37:53Date Closed:2018-01-02 08:30:28.000-0600
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Applications/app_confbridge
Versions:10.3.0 Frequency of
Occurrence		Constant
Related
Issues:
is a clone ofASTERISK-18885 confbridge, video hangs, Exceptionally long queue length queuing to Bridge
Environment:Debian Squeeze 64 bits in KVM virtual machine, host running same distro.Attachments:( 0) backtrace.txt
( 1) backtrace.txt
( 2) debug
( 3) from_to-OFFICE.conf
( 4) from_to-OFFICE.conf
( 5) full.2012043018h20m
( 6) full2012050117h47m.log
( 7) full2012050417h53m.log
( 8) sip.conf
( 9) sip.conf
(10) warning.txt
Description:We testing confbridge with video with  follow_talker , connected with 2 clients, IP Video phone Grandstream GXV3175 and GXV3006 in h263p format

[...]
[2012-04-20 13:19:21] WARNING[31129] channel.c: Exceptionally long queue length queuing to Local/888@OFFICE-Numbers-f5c6;2
[2012-04-20 13:19:22] WARNING[31130] channel.c: Exceptionally long queue length queuing to Local/888@OFFICE-Numbers-f5c6;1
[2012-04-20 13:19:23] WARNING[31125] channel.c: Exceptionally long queue length queuing to Local/888@OFFICE-Numbers-5ad9;1

Video hangs on both phones. After hanging up the call, channels are'nt hanged up:


zone-s*CLI> core show channels concise
Local/888@OFFICE-Numbers-5ad9;2!OFFICE-Numbers!888!6!Up!ConfBridge!888!160!!!3!1136!(None)!1334920712.16
Bridge/0x7f2a581e2e58-input!default!s!1!Up!(None)!!!!!3!1131!(None)!1334920717.17
Bridge/0x7f2a581e2e58-output!default!s!1!Up!(None)!!!!!3!1131!(None)!1334920717.18

and have to do it manually

zone-s*CLI> confbridge kick 888 Local/888@OFFICE-Numbers-5ad9;2
Kicking Local/888@OFFICE-Numbers-5ad9;2 from confbridge 888
   -- <Bridge/0x7f2a581e2e58-input> Playing 'confbridge-leave.g722' (language 'fr')
[2012-04-20 13:38:17] WARNING[31125]: file.c:829 ast_readaudio_callback: Failed to write frame
   -- <Local/888@OFFICE-Numbers-5ad9;2> Playing 'conf-kicked.g722' (language 'fr')
 == Spawn extension (OFFICE-Numbers, 888, 6) exited non-zero on 'Local/888@OFFICE-Numbers-5ad9;2'

See attached debug file.

--
Daniel
Comments:By: tootai (tootai) 2012-04-20 06:47:58.775-0500

Debug level 15
By: tootai (tootai) 2012-04-20 07:36:41.640-0500

I tested with 3 devices in h263p, the GrandStream phones plus Ekiga and got a crash. Attached is backtrace.txt, asterisk compiled with not optimized, debug and better backtrace.
By: tootai (tootai) 2012-04-20 07:37:28.264-0500

Compile option not optimized, debug and better backtrace
By: Stefan Schmidt (schmidts) 2012-04-24 02:35:36.627-0500

please also attach the output of "core show locks" when this happens. Sounds like a deadlock problem for me.
Thanks
By: tootai (tootai) 2012-04-24 07:45:02.539-0500

zone-s*CLI> core show locks

=======================================================================
=== Currently Held Locks ==============================================
=======================================================================
===
=== <pending> <lock#> (<file>): <lock type> <line num> <function> <lock name> <lock addr> (times locked)
===
=======================================================================

zone-s*CLI>

Empty output
By: Matt Jordan (mjordan) 2012-04-24 13:53:40.679-0500

1. The backtrace you've attached does not contain any symbols.  When creating backtraces from a core file, please follow the instructions at https://wiki.asterisk.org/wiki/display/AST/Getting+a+Backtrace

2. The DEBUG log you've attached does not illustrate the problem description, e.g., it does not contain any log statements regarding a long queue length.  Please attach a DEBUG log illustrating the problem.
By: tootai (tootai) 2012-04-25 04:27:37.019-0500

New backtrace file.
By: tootai (tootai) 2012-04-25 04:36:29.636-0500

Warnings concerning the problem
By: Richard Mudgett (rmudgett) 2012-04-25 11:15:07.995-0500

FYI When you are done sending requested information you need to send back the issue.  Otherwise the issue appears to be waiting on you to respond and falls off the radar.
By: tootai (tootai) 2012-04-25 12:20:57.333-0500

Datas are updated
By: Matt Jordan (mjordan) 2012-04-30 08:22:42.120-0500

Again, the backtrace you've provided does not appear to be generated from a system with the correct menuselect options enabled.  As such, it does not provide sufficient information to assist in any way with this problem.  

That being said, I'm not sure it would be terribly useful in the first place, since this does not appear to be a crash.

Typically, when a DEBUG log is requested, we are requesting a log that contains all log levels, from DEBUG up to ERROR.  At a minimum, this would look like the following in your logger.conf:

{noformat}
full => error,warning,notice,verbose,debug
{noformat}

What you've provided is simply the DEBUG information coupled with the WARNING information, in separate logs.  This requires bug marshals to piece together the information; in addition, the lack of VERBOSE, NOTICE, and ERROR information means that crucial information may be missing.  In the future, please provide a log that meats the format specified above.

Finally, you've provided a DEBUG log that goes from 13:18:32 to 13:24:23.  The WARNINGs in your warning log, however, occur at 14:09:05 and onward.  The DEBUG log does not contain the information that corresponds to when the actual problems began.

That being said, there are some obvious red flags in the WARNING log:

{noformat}
[2012-04-20 14:09:05] WARNING[30988] chan_sip.c: Got Siren7 offer at 24000 bps, but only 32000 bps supported; ignoring.
{noformat}

This implies that the negotiation between two endpoints failed, where one endpoint is using the Siren7 codec at one frame rate (32k) while the other endpoint offered at a different frame rate (24k).  Since negotiation between the two endpoints failed, its possible that one of them is having frames queued up on it, and nothing is reading it off.

Another red flag:

{noformat}
[2012-04-20 14:09:13] WARNING[31334] chan_sip.c: This function can only be used on SIP channels.
{noformat}

You're attempting to read a SIP header on a non-SIP channel.  This implies a configuration error in your dialplan.  Please attach your extensions.conf, as this may be contributing to your problems.

Please attach a log generated with the format specification defined previously.  Please also turn "sip set debug on", so that the negotiation between the different endpoints can be verified.  Please also attach your sip.conf.


By: tootai (tootai) 2012-04-30 11:08:35.084-0500

For sure, active Compiler Flags are Dont_Optimize, Debug_Threads, Loadable_Modules and Better_Backtraces

We will restart the hole procedure including patching sources with 10.3.1.

We saw the Siren Warnings but as both phones and VoIP software are using g711u and h363p, and that we had audio and video we didn't care.

Concerning the Warning chan_sip.c: This function can only be used on SIP channels, it comes from a Set(CHANNEL(musicclass)=MeetMe) used in the ConfBridge context

--
Daniel
By: tootai (tootai) 2012-04-30 12:04:07.355-0500

extensions and sip conf (mandatory part)
By: Matt Jordan (mjordan) 2012-04-30 12:39:21.809-0500

Just as an FYI, the warning about a function only being able to be used on a SIP channel is actually due to this in your dialplan:

{noformat}
exten => _888,n,GotoIf($["${SIP_HEADER(X-TOOTAI-LANGUAGE)}" != "" ]?:languageOK)
{noformat}

The channel in 888@OFFICE-Numbers is a local channel, which will never have the SIP header X-TOOTAI-LANGUAGE.

I'll keep this in Waiting For Feedback until the DEBUG log is posted (the most recent log contains VERBOSE through ERROR; I assume since you noted that you posted the extensions/sip.conf that the log wasn't generated yet)
By: tootai (tootai) 2012-05-01 06:49:13.364-0500

I think you missed the full logs full.2012043018h20m [ 43494 ] attached before sip and extensions conf files.

By: Matt Jordan (mjordan) 2012-05-01 08:07:33.404-0500

No, I didn't.  That log does not contain DEBUG statements, although it does have sip set debug on.

Your logger.conf *must* include the debug format specifier, as shown previously:

{noformat}
full => error,warning,notice,verbose,debug
{noformat}
By: tootai (tootai) 2012-05-01 10:53:02.847-0500

My bad, debug is seeted in logger => full, I should have made a mistake when recording.

Now it's OK, sorry for that.
By: Matt Jordan (mjordan) 2012-05-04 08:17:50.782-0500

The good news is that the log you've attached is a DEBUG log, with 'sip set debug on' turned on in Asterisk.

The bad news is that it does not contain any information pertaining to the issue you've described.  The log is a capture of a SIP registration, along with several NOTIFY requests and OPTIONS requests.  Those having nothing to do with the ConfBridge application, nor do they have anything to do with the WARNING message you've reported.

Please attach a DEBUG log that illustrates the calls going into the ConfBridge application, and that illustrate the issue you've described here.
By: tootai (tootai) 2012-05-04 11:04:20.537-0500

Hope we got it right now !
By: tootai (tootai) 2012-05-04 11:04:46.466-0500

A new one was uploaded
By: Matt Jordan (mjordan) 2012-05-14 12:22:06.556-0500

That log file looks good, thanks!
By: Joshua C. Colp (jcolp) 2017-12-19 05:58:22.906-0600

The ConfBridge application and API was considerably rewritten since this issue was filed. Are you still experiencing it under a supported version of Asterisk?
By: Asterisk Team (asteriskteam) 2018-01-02 08:30:28.518-0600

Suspended due to lack of activity. This issue will be automatically re-opened if the reporter posts a comment. If you are not the reporter and would like this re-opened please create a new issue instead. If the new issue is related to this one a link will be created during the triage process. Further information on issue tracker usage can be found in the Asterisk Issue Guidlines [1].
[1] https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines