EAGI audio output lags

jaddle · January 21, 2010, 8:23pm

Hello,

I have a system that records a conference (voip-info.org/wiki/view/Aste … Conference) using eagi. For the most part, this works, however, I’ve been finding that there’s a lag in the audio data coming out of asterisk, and that this lag increases gradually as long as the conference is active. After a 45 minute call, the delay is about 20 seconds! Restarting the conference resets this delay to nothing.

I also notice little ‘blips’ in the audio. Every few seconds, there’s a tiny little gap in the sound. I assume the accumulation of these blips is what’s causing the delay.

Is this a known problem? Is there any workaround?

I’m using the asterisk from Debian, version 1.4.21.2~dfsg-3+lenny1, in case that makes a difference.

jaddle · January 23, 2010, 12:23am

By the way, I’m testing this by starting the eagi application in the conference and then counting to 30. Then I stop the eagi app, and look at the data it has saved. It saved the correct amount of data (within a second or so, anyway - I haven’t been too precise with timing that), but it is always delayed. Just now, I tested with a new conference and saw no delay at all. After 15 minutes, the delay was up to 10 seconds.

jaddle · January 23, 2010, 11:21pm

I just noticed some error messages popping up in the logs:

[Jan 21 15:12:46] WARNING[8574] conference.c: processed frame frequency variation, name => ConferenceA_test, tf_count => 50, tf_diff => 950, tf_frequency => 19.0000

There are several lines like this, with tf_diff varying between 912-1083, and tf_frequency from 18.24-21.66. Does anyone know what this might mean?

jaddle · January 23, 2010, 11:31pm

And I just did some more testing, and discovered that I’m seeing the same lag problem on another machine running meetme! (this is on the same hardware, but in the dom0 of the xen system, whereas the other server was in a domU).

So it looks like the problem is probably related to something else in asterisk. I’m going to try upgrading to 1.6 to see if that works.

jaddle · February 10, 2010, 8:41pm

So, I’ve tried upgrading to 1.6, and now I’m seeing all kinds of new errors - basically 1.6 just isn’t working at all. Any channel connects to any conference (meetme or app_conference or appkonference) just results in a flood of errors, seemingly before it even gets to the conference.

[Feb 10 14:14:37] WARNING[15571]: channel.c:1065 __ast_queue_frame: Unable to write to alert pipe on Local/conference@veco-044d;1 (qlen = 0): Broken pipe!
[Feb 10 14:14:37] WARNING[15571]: channel.c:1065 __ast_queue_frame: Unable to write to alert pipe on Local/conference@veco-044d;1 (qlen = 1): Broken pipe!
– Executing [conference@veco:2]
NoOp(“Local/conference@veco-044d;2”, “Trying to start conference
ConferenceA_test”) in new stack
– Executing [conference@veco:3]
Konference(“Local/conference@veco-044d;2”, “ConferenceA_test”) in new stack
[Feb 10 14:14:38] WARNING[15571]: channel.c:1065 __ast_queue_frame: Unable to write to alert pipe on Local/conference@veco-044d;1 (qlen = 2): Broken pipe!
[repeated many, many times]

[Feb 10 14:14:40] WARNING[15571]: channel.c:1045 __ast_queue_frame: Exceptionally long voice queue length queuing to
Local/conference@veco-044d;1
[Feb 10 14:14:40] WARNING[15571]: channel.c:1045 __ast_queue_frame: Exceptionally long voice queue length queuing to
Local/conference@veco-044d;1
[also repeated many, many times]

Any suggestions are very welcome. Other people must have seen this kind of error when upgrading to 1.6!

system · February 11, 2010, 3:21am

The reason why nobody is responding is because you haven’t posted any code which makes this extremely difficult to debug. You also mentioned that you are running your Asterisk server on Xen which has known timing issues that cause delays in audio (which sounds exactly like what you are experiencing). Can you please give us all of the information about your system / build, as well as post your code and a full logfile of the call running?

jaddle · February 11, 2010, 3:01pm

Thanks for the reply.

Sorry I haven’t posted anything - I’m really not sure what files might be useful for debugging this, and didn’t want to dump my entire configuration directory here. I’ve pasted what I hope will help below, but please let me know if there’s anything else that I could provide.

Also, I’ve seen the exact same behaviour in the xen dom0 and the domU (the domU is being used for testing, while the dom0 is the main server).

Here is the (I hope) relevant part of extensions.conf:

exten => meetme,1,Answer()
exten => meetme,n,MeetMe(${conference}_${tour},1qd)

On the domU’s, since I can’t use meetme, I use app_conference instead:
exten => conference,1,Answer()
exten => conference,n,Conference(${conference}_${tour}/S/1)

exten => mp3stream,1,Answer
exten => mp3stream,n,Wait(1)
exten => mp3stream,n,EAGI(mp3stream.sh|${tour})

Calls are made using the manager interface with a queries like these:
when adding a sip call to the conference:
Action: originate
Channel: Local/meetme@veco/n
Context: veco
Exten: localveco@test.vecotourism.org
Priority: 1
Variable: tour=test
Variable: dir=
Variable: conference=ConferenceA
Variable: provider=teliax
Variable: extravalue=veco@test.vecotourism.org
Variable: title=veco@test.vecotourism.org

when adding the eagi application:
Action: originate
Channel: Local/meetme@veco/n
Context: veco
Exten: mp3stream
Priority: 1
Variable: tour=test
Variable: dir=
Variable: conference=ConferenceA
Variable: provider=teliax
Variable: extravalue=mp3stream
Variable: title=mp3stream

And here is the log of a typical call
Adding the sip connection:

[Feb 11 09:36:06] NOTICE[28568]: chan_sip.c:15094 handle_request_subscribe: Received SIP subscribe for peer without mailbox: veco
Really destroying SIP dialog ‘d222ef74-8815-df11-85d5-0013026fdd9c@scaph’ Method: SUBSCRIBE
== Parsing ‘/etc/asterisk/manager.conf’: Found
== Parsing ‘/etc/asterisk/manager.d/README.conf’: Found
== Parsing ‘/etc/asterisk/manager.d/veco.conf’: Found
== Manager ‘veco’ logged on from 127.0.0.1
– Executing [meetme@veco:1] Answer(“Local/meetme@veco-a8ba,2”, “”) in new stack
– Executing [meetme@veco:2] MeetMe(“Local/meetme@veco-a8ba,2”, “ConferenceA_test|1qd”) in new stack
[Feb 11 09:36:07] WARNING[12152]: chan_zap.c:5400 zt_new: Unable to get parameters, assuming MULAW
– Created MeetMe conference 1023 for conference ‘ConferenceA_test’
> Channel Local/meetme@veco-a8ba,1 was answered.
– Executing [localveco@vecotourism.org@veco:1] Answer(“Local/meetme@veco-a8ba,1”, “”) in new stack
– Executing [localveco@vecotourism.org@veco:2] Wait(“Local/meetme@veco-a8ba,1”, “1”) in new stack
== Manager ‘veco’ logged off from 127.0.0.1
– Executing [localveco@vecotourism.org@veco:3] NoOp(“Local/meetme@veco-a8ba,1”, "localveco@vecotourism.org") in new stack
– Executing [localveco@vecotourism.org@veco:4] Dial(“Local/meetme@veco-a8ba,1”, “SIP/veco”) in new stack
– Called veco
– SIP/veco-08627a38 is ringing
== Parsing ‘/etc/asterisk/manager.conf’: Found
== Parsing ‘/etc/asterisk/manager.d/README.conf’: Found
== Parsing ‘/etc/asterisk/manager.d/veco.conf’: Found
== Manager ‘veco’ logged on from 127.0.0.1
== Manager ‘veco’ logged off from 127.0.0.1
[Feb 11 09:36:11] WARNING[12153]: rtp.c:1145 ast_rtp_read: RTP Read too short
– SIP/veco-08627a38 answered Local/meetme@veco-a8ba,1
REGISTER attempt 1 to veco@voip-co1.teliax.com
REGISTER attempt 2 to veco@voip-co1.teliax.com
Really destroying SIP dialog ‘90f4c374-8815-df11-85d5-0013026fdd9c@scaph’ Method: REGISTER
Really destroying SIP dialog ‘210a461b6c90b8e84786369f7b3b57af@72.55.143.26’ Method: REGISTER

When I add the eagi application, I see this:

== Parsing ‘/etc/asterisk/manager.conf’: Found
== Parsing ‘/etc/asterisk/manager.d/README.conf’: Found
== Parsing ‘/etc/asterisk/manager.d/veco.conf’: Found
== Manager ‘veco’ logged on from 127.0.0.1
– Executing [meetme@veco:1] Answer(“Local/meetme@veco-9353,2”, “”) in new stack
– Executing [meetme@veco:2] MeetMe(“Local/meetme@veco-9353,2”, “ConferenceA_test|1qd”) in new stack
> Channel Local/meetme@veco-9353,1 was answered.
– Executing [stream@veco:1] Answer(“Local/meetme@veco-9353,1”, “”) in new stack
– Executing [stream@veco:2] EAGI(“Local/meetme@veco-9353,1”, “oggstream.sh|test”) in new stack
– Launched AGI Script /usr/share/asterisk/agi-bin/oggstream.sh
– Executing [meetme@veco:1] Answer(“Local/meetme@veco-9036,2”, “”) in new stack
– Executing [meetme@veco:2] MeetMe(“Local/meetme@veco-9036,2”, “ConferenceA_test|1qd”) in new stack
> Channel Local/meetme@veco-9036,1 was answered.
== Manager ‘veco’ logged off from 127.0.0.1
– Executing [mp3stream@veco:1] Answer(“Local/meetme@veco-9036,1”, “”) in new stack
– Executing [mp3stream@veco:2] Wait(“Local/meetme@veco-9036,1”, “1”) in new stack
– Executing [mp3stream@veco:3] EAGI(“Local/meetme@veco-9036,1”, “mp3stream.sh|test”) in new stack
– Launched AGI Script /usr/share/asterisk/agi-bin/mp3stream.sh
== Parsing ‘/etc/asterisk/manager.conf’: Found
== Parsing ‘/etc/asterisk/manager.d/README.conf’: Found
== Parsing ‘/etc/asterisk/manager.d/veco.conf’: Found
== Manager ‘veco’ logged on from 127.0.0.1
== Manager ‘veco’ logged off from 127.0.0.1
== Parsing ‘/etc/asterisk/manager.conf’: Found
== Parsing ‘/etc/asterisk/manager.d/README.conf’: Found
== Parsing ‘/etc/asterisk/manager.d/veco.conf’: Found
== Manager ‘veco’ logged on from 127.0.0.1
== Spawn extension (veco, meetme, 2) exited non-zero on ‘Local/meetme@veco-9353,2’
== Manager ‘veco’ logged off from 127.0.0.1
== Spawn extension (veco, stream, 2) exited non-zero on ‘Local/meetme@veco-9353,1’
== Parsing ‘/etc/asterisk/manager.conf’: Found
== Parsing ‘/etc/asterisk/manager.d/README.conf’: Found
== Parsing ‘/etc/asterisk/manager.d/veco.conf’: Found
== Manager ‘veco’ logged on from 127.0.0.1
== Spawn extension (veco, meetme, 2) exited non-zero on ‘Local/meetme@veco-9036,2’
== Manager ‘veco’ logged off from 127.0.0.1
== Spawn extension (veco, mp3stream, 3) exited non-zero on ‘Local/meetme@veco-9036,1’
== Parsing ‘/etc/asterisk/manager.conf’: Found
== Parsing ‘/etc/asterisk/manager.d/README.conf’: Found
== Parsing ‘/etc/asterisk/manager.d/veco.conf’: Found
== Manager ‘veco’ logged on from 127.0.0.1
== Manager ‘veco’ logged off from 127.0.0.1

jaddle · February 11, 2010, 3:14pm

Also, here is a bit of audio recorded from the conference via the eagi script.

It’s a 300K wav file. http://www.vecotourism.org/audio.wav

The script is just a simple cat /dev/fd/4 > output.raw

I then converted that to wav with

This was recorded after only a few minutes in the conference, so there isn’t any noticeable delay yet. Another sample I recorded 10 minutes later showed several seconds of delay. Also, in this sample, you can hear a little interruption in the audio in the middle of the word ‘five’. About 131 samples are at 0 - I imagine the cumulative effects of these little interruptions are what is causing the delay.