[Home]

Summary:ASTERISK-04122: adjustment to MAX_TIMESTAMP_SKEW to work around chan_zap/zaptel bug
Reporter:Andrew Kohlsmith (akohlsmith)Labels:
Date Opened:2005-05-09 15:55:39Date Closed:2011-06-07 14:10:41
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Channels/chan_iax2
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) chan_iax2.ts-skew-reduce.diff.txt
( 1) chan_zap.send_cng.diff3.txt
Description:There is a bug in chan_zap and/or the zaptel driver which manifests itself when the zaptel channel is generating DTMF.  Namely, there is no audio available from the channel.  This causes nastiness as there are no frames being generated if there is no audio available, and the current MAX_TIMESTAMP_SKEW value of 640ms in chan_iax2.c is far too long to work around this.

This patch reduces that value to 160ms.  If the difference between the current time and the next predicted timestamp is greater than 160ms, chan_iax2 will send the next voice frame using the current timestamp rather than the predicted value.  This causes the receiving jitter buffer to work correctly.

****** ADDITIONAL INFORMATION ******

What was happenning:

464   4.485971  192.168.2.1 -> 192.168.2.2  IAX2 Mini packet, source call# 18, timestamp 4520ms, GSM compression
465   4.501222  192.168.2.2 -> 192.168.2.1  IAX2 Mini packet, source call# 2, timestamp 4520ms, GSM compression
466   4.501259  192.168.2.2 -> 192.168.2.1  IAX2 DTMF, source call# 2, timestamp 4503ms digit 2
467   4.502800  192.168.2.1 -> 192.168.2.2  IAX2 IAX, source call# 18, timestamp 4503ms ACK
468   4.520872  192.168.2.2 -> 192.168.2.1  IAX2 Mini packet, source call# 2, timestamp 4540ms, GSM compression
469   4.540865  192.168.2.2 -> 192.168.2.1  IAX2 Mini packet, source call# 2, timestamp 4560ms, GSM compression
470   4.560867  192.168.2.2 -> 192.168.2.1  IAX2 Mini packet, source call# 2, timestamp 4580ms, GSM compression
471   4.580906  192.168.2.2 -> 192.168.2.1  IAX2 Mini packet, source call# 2, timestamp 4600ms, GSM compression
472   4.600881  192.168.2.2 -> 192.168.2.1  IAX2 Mini packet, source call# 2, timestamp 4620ms, GSM compression
473   4.620879  192.168.2.2 -> 192.168.2.1  IAX2 Mini packet, source call# 2, timestamp 4640ms, GSM compression
474   4.640883  192.168.2.2 -> 192.168.2.1  IAX2 Mini packet, source call# 2, timestamp 4660ms, GSM compression
475   4.660925  192.168.2.2 -> 192.168.2.1  IAX2 Mini packet, source call# 2, timestamp 4680ms, GSM compression
476   4.680900  192.168.2.2 -> 192.168.2.1  IAX2 Mini packet, source call# 2, timestamp 4700ms, GSM compression
477   4.700895  192.168.2.2 -> 192.168.2.1  IAX2 Mini packet, source call# 2, timestamp 4720ms, GSM compression
478   4.720900  192.168.2.2 -> 192.168.2.1  IAX2 Mini packet, source call# 2, timestamp 4740ms, GSM compression
479   4.726018  192.168.2.1 -> 192.168.2.2  IAX2 Mini packet, source call# 18, timestamp 4540ms, GSM compression
480   4.740943  192.168.2.2 -> 192.168.2.1  IAX2 Mini packet, source call# 2, timestamp 4760ms, GSM compression
481   4.746021  192.168.2.1 -> 192.168.2.2  IAX2 Mini packet, source call# 18, timestamp 4560ms, GSM compression
482   4.760912  192.168.2.2 -> 192.168.2.1  IAX2 Mini packet, source call# 2, timestamp 4780ms, GSM compression
483   4.766045  192.168.2.1 -> 192.168.2.2  IAX2 Mini packet, source call# 18, timestamp 4580ms, GSM compression

As you can see, when 192.168.2.1 was generating the 200ms DTMF tone it was NOT sending any audio back to 192.168.2.2.

The jitter buffer on 192.168.2.2 was (correctly) seeing 200ms of packet loss.  Unfortunately, when 192.168.2.1 got back to sending audio again, it was sending it with timestamps 200ms in the past, which caused the jitter buffer to see those frames as late and to discard them.  The more DTMF you generate, the later these packets get.  The end result: one-way audio for as long as it took for the jitter buffer to age-out the high jitter.  (it was already cutting off the "5% highest" and "5% lowest" jitter values.

Please note that this patch is a workaround; the real bug still remains in that chan_zap/zaptel is not making any audio available for the duration of the DTMF tone it is sending.  stevek, grolloj, pcadach and myself have been digging around this and it seems to be a driver issue.  The driver correctly zeroes out the audio received, but it is not made available to read().  I'll be opening a bug for that when I get some more information.

In the meantime, this patch works VERY well and does not seem to cause any 'damage'.  It can CAUSE higher jitter but that seems to be a good thing in this case.

Disclaimer is on file.
Comments:By: stevekstevek (stevekstevek) 2005-05-09 16:06:35

Correction:  "It can CAUSE higher jitter but that seems to be a good thing in this case."  --- It actually causes the receiver to see the lack of frames during this period as LOSS, not jitter.  So, the receiver will:

a) Include this loss in it's statistics.
b) Interpolate for the loss during this period.

Neither of these are optimal.  

I'm guessing the reason chan_zap isn't sending audio back during this period is because it wants to avoid sending back to the user any echo of the generated DTMF audio.  That makes sense.

Ideally, chan_zap would either (a) send "silent" audio frames, or (b) generate a CNG frame, which would tell chan_iax2 (on the sending side) to stop generating sequential timestamps, and the reciever not to expect audio for a bit (so it doesn't consider the not-present frames to be lost).
By: Andrew Kohlsmith (akohlsmith) 2005-05-09 18:11:15

While I am not going to argue with you, Steve, I don't understand why NOT having the jitter buffer show this as loss is suboptimal.  You really *did* lose these frames, and in fact the frames you get when the other side starts sending again (packet 479 above) have a timestamp that is 200ms earlier than it should have.

At least in my mind, you *do* have loss, and it should be reported, and since there is loss, the jitter buffer interpolating these lost frames is a good thing, and a right thing.

As you said in IRC it's a loss of frames from a bug in chan_zap/zaptel and not from the network, but hey, loss is loss.  :-)

Also, just to get your comments from IRC in the bug tracker -- reducing the value of MAX_TIMESTAMP_SKEW can potentially cause troubles if the system is so heavily loaded down that the linux scheduler causes the frames to be delayed by around 160ms... but that's a LOT of load; I'd be surprised if the system was running well to begin with and didn't have audio issues far earlier on!
By: Andrew Kohlsmith (akohlsmith) 2005-05-16 21:02:33

chan_zap.send_cng.diff.txt is a better fix -- it causes chan_zap to emit an AST_FRAME_CNG back to the bridged channel before calling down to zaptel to generate the DTMF.  This causes chan_iax2.c to resync its outgoing timestamps correctly and thus the JB works *perfectly*.

Mad, mad mad mad props to file and MikeJ for helping me on this; file's the one who found a mini-bug in channel.c that caused it to drop CNG frames on the floor.
By: Andrew Kohlsmith (akohlsmith) 2005-05-18 16:06:26

chan_zap.send_cng.diff3.txt uses ast_queue_frame() instead of ast_write() to write the CNG frame back to the bridge.  It also has the fix for channel.c which allows CNG frames to be bridged.  :-)  This solves the problem nicely, but I'm still working on figuring out why chan_zap.c isn't seeing ANY data while DTMF is being played out to TDM.
By: stevekstevek (stevekstevek) 2005-05-18 16:17:52

OK, from what I see, this patch does three things:

Chunk 1:  In ast_write, it causes AST_FRAME_CNG to be handled specially, and be written directly to the channel.  (whereas before, it ended up going through ast_translate if there was a translator).

My question here is, would it make more sense to just let the translator pass this through instead?  Nah, I think this choice makes more sense..

Chunk 2:  actually makes the bridge pass it through.

Chunk 3: Makes zaptel generate a CNG frame when it's sending DTMF.

====================

I think this is all fine, but we ought to test this, because CNG frames might end up being passed to places they weren't previously expected after this change goes in.  But, in the end, as we get to full CNG support, 1,2 seem correct.  (3) still seems a bit awkward, but as long as chan_zap isn't going to give us audio while it sends DTMF, this is a reasonable thing to do.
By: Andrew Kohlsmith (akohlsmith) 2005-05-18 17:35:13

correct.  Chunk 1 was file's solution to why ast_write() wasn't sending CNG frames over.  You'll note later on in the channel.c that CNG frames set up "self timed mode" in the zaptel driver, but I have no idea what that's supposed to do.  :-)
By: Michael Jerris (mikej) 2005-05-18 19:34:33

chan_iax2.ts-skew-reduce.diff.txt  should be ready,   chan_zap.send_cng.diff3.txt  needs feedback from mark.
By: Mark Spencer (markster) 2005-05-18 19:53:21

This needs an actual fix in zaptel if there's truly a problem there.  I don't think 160 is a good choice because then simply missing a single frame could push the timestamp out into some odd-ball number instead of having a clean break.
By: Mark Spencer (markster) 2005-05-18 19:56:53

Nevermind, 160 ms != 160 samples
By: Digium Subversion (svnbot) 2008-01-15 15:35:19.000-0600

Repository: asterisk
Revision: 5717

U   trunk/channels/chan_iax2.c

------------------------------------------------------------------------
r5717 | markster | 2008-01-15 15:35:19 -0600 (Tue, 15 Jan 2008) | 2 lines

Merge skew reduction (bug ASTERISK-4122)

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=5717