[Home]

Summary:ASTERISK-08310: [patch] DTMF fails and one-way-audio after negative timestamp.
Reporter:Harmen van der Wal (harmen)Labels:
Date Opened:2006-12-08 06:40:49.000-0600Date Closed:2007-01-25 13:25:23.000-0600
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Channels/chan_iax2
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) jb_next.patch
Description:Frames with a negative timestamp can not be dequeued from the
jitterbuffer. Subsequent frames then get stuck behind this frame
too, resulting in DTMF not working or one-way-audio.

This can happen with the following setup:
iaxclient -> asterisk #1 -> asterisk #2,
where asterisk #1 and asterisk #2 both use a (new style)
jitterbuffer. The frames with a negative timestamp originate on
asterisk #1 and become stuck in the jitterbuffer queue on asterisk #2.

Two solutions come to mind:

1) Don't send frames with a negative timestamp.

calc_timestamp@chan_iax2.c calculates the timestamp by taking the difference of the delivery time and the channel offset. Early on in the call this can lead to negative values (which show up in the log as big positive numbers, because they are formatted unsigned).

Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 001 Type: VOICE   Subclass: 2
  Timestamp: 4294967122ms  SCall: 00002  DCall: 00001 [192.168.1.10:4569]
Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 002 Type: IAX     Subclass: ACK
  Timestamp: 4294967122ms  SCall: 00001  DCall: 00002 [192.168.1.10:4569]

I guess delivery time is set by the sender and the channel offset is set by the receiver at a slightly later time. I am not quite sure if this is a bug. Besides for the jitterbuffer, the negative timestamps don't appear to cause problems, as far as I can tell.

2) Do dequeue frames with a negative timestamp.

See the attached jb_next.patch.

Queue_next and queue_last@jitterbuffer.c return a timestamp or -1 if the queue is empty. This doesn't work if the timestamp can be -1. Perhaps the timestamp is better modified as an argument pointer, but I don't think it causes problems besides for jb_next.

This the same bug as http://bugs.digium.com/view.php?id=6011.

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

To consistently reproduce the DTMF problem I made the following
changes to an else default configuration.

asterisk #1 (192.168.1.1)

iax.conf
jitterbuffer=yes

extensions.conf
exten => 608,1,Dial(IAX2/guest@192.168.1.10)

asterisk #2 (192.168.1.10)

iax.conf
jitterbuffer=yes

Use iaxclient (wx) to call asterisk #1. Hear the demo congratulations
on the asterisk #1. Dial 608 on the dialpad. Hear the demo congratulations
on the asterisk #2. Dial any extension. The DTMF frames are received
on asterisk #2 but do not work.
To consistently reproduce the one-way-audio problem I used the following.

asterisk #1 (192.168.1.1)

iax.conf
jitterbuffer=yes

extensions.conf
exten => 604,1,Dial(IAX2/guest@192.168.1.10/601||gt)
exten => 604,n,agi(agi://192.168.1.10)
exten => 604,n,Dial(IAX2/guest@192.168.1.10/602||gt)

asterisk #2 (192.168.1.10)

iax.conf
jitterbuffer=yes

extensions.conf
exten => 601,1,Playback(demo-echotest);
exten => 602,1,Echo

Run ~/src/asterisk-1.2/agi/fastagi-test

Use iaxclient (wx) to call asterisk #1. Hear the demo
congratulations. Dial extension 604. Hear the demo echo test message
from asterisk #2. Hear the fast-agi test. Try the echo test. It fails.


Comments:By: Nic Bellamy (nic_bellamy) 2006-12-10 15:39:06.000-0600

Related question to this - where are the large timestamps coming from?

I did a search through captures of about 1,500 call-hours of production traffic, and found SIP->IAX2->SIP calls where this happened.

Here's an example:

Mini voice frames are flowing fine, then a full voice packet (line 6) is sent with a whacky timestamp.

This timestamp is interesting:

5       268.346780  172.16.9.10 -> 172.16.254.10 IAX2 Mini packet, source call# 2, timestamp 34545ms, iLBC Free Compression
6       268.366713  172.16.9.10 -> 172.16.254.10 IAX2 Voice, source call# 2, timestamp 3758130959ms, iLBC Free Compression
7       268.378125 172.16.254.10 -> 172.16.9.10  IAX2 Mini packet, source call# 26, timestamp 34576ms, iLBC Free Compression

Some quick calculations...:

3758130959 = 0xe000870f

0xe000870f - 0xe000000 = 0x870f = 34575

Ie. it appears the three high bits are getting set in the timestamp, in that when you take them off, the timestamp looks perfectly sane again.

Asterisk 1.2.7.1 FYI - too many other things break for us with anything more recent (mainly just waiting on ASTERISK-7849 now).


By: Harmen van der Wal (harmen) 2006-12-11 08:30:22.000-0600

Hm, it appears my "large" timestamps are of a different kind. In my case they're
really small negatives. For instance when delivery = 1165841516sec+988882usec and offset = 1165841517sec+40000usec then the the timestamp is -52.
Because printf("Timestamp: %05lums\n", -52) prints 4294967244ms the log shows:

Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 001 Type: VOICE   Subclass: 2
  Timestamp: 4294967244ms  SCall: 00002  DCall: 00001 [192.168.1.10:4569]

I can't explain the three high bits though. I wonder if and how threy're related.
By: Harmen van der Wal (harmen) 2006-12-19 07:57:56.000-0600

I forgot to mention one detail required to reproduce the problem: asterisk #1 and #2 need to be configured for different codecs, or the problem will not occur.

asterisk #1
iax.conf
allow=gsm

asterisk #2
iax.conf
allow=ilbc

The result will be:

   -- IAX2/192.168.1.10:4569-2 answered IAX2/192.168.1.1:32840-1
   -- Attempting native bridge of IAX2/192.168.1.1:32840-1 and IAX2/192.168.1.10:4569-2
   -- Operating with different codecs 2[0x2 (gsm)] 1024[0x400 (ilbc)] , can't native bridge...
By: jeff oconnell (jeff_oconnell) 2006-12-19 23:18:42.000-0600

serge,

you marked this as having a closed duplicate ( bug 0006011 ).
does that mean this report ( and  the patch ) won't be considered?

i'm going to do some real-world testing with harmen's patch soon,
and can speed up my test schedule if that'll help get the patch applied.
By: Serge Vecher (serge-v) 2006-12-26 14:41:26.000-0600

jeff_oconnell: successful tests, preferably from several reporters, do help get patches in...
By: Anthony LaMantia (alamantia) 2007-01-05 16:40:05.000-0600

has anyone tested this code?
By: jeff oconnell (jeff_oconnell) 2007-01-07 12:31:16.000-0600

alamantia: i'll be testing this code this week.
By: Joshua C. Colp (jcolp) 2007-01-25 13:25:22.000-0600

Fixed in 1.2 as of revision 52264, 1.4 as of revision 52265, and trunk as of revision 52266. Thanks for the fix - it should knock out some others and your explanation was great.