[Home]

Summary:ASTERISK-04626: chan_iax2 sending crazy timestamps that completely freak remote jitter buffer
Reporter:Steve Davies . (stevedavies)Labels:
Date Opened:2005-07-19 16:38:07Date Closed:2008-01-15 15:42:09.000-0600
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Core/General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) crazy-timestamps.txt
Description:
This is, I'd say, the same bug as ASTERISK-4609 which was closed.

Updated a system to CVS-HEAD 05-07-19, which now has rizzo's redone timestamp stuff.

The updated system talks to another with CVS-HEAD 05-06-01.  After the update, we had no audio to speak of between the systems.

Looking into it and enabling a packet trace, here's what is being received from the updated system.  In short, crazy timestamps:

Jul 19 17:05:05 VERBOSE[32420] Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 002 Type: VOICE  Subclass: 138
Jul 19 17:05:05 VERBOSE[32420] logger.c:    Timestamp: 1717987350ms  SCall: 00003  DCall: 00002 [196.22.2.194:4569]
Jul 19 17:05:05 VERBOSE[32420] logger.c: Rx-Frame Retry[ No] -- OSeqno: 004 ISeqno: 002 Type: VOICE   Subclass: 138
Jul 19 17:05:05 VERBOSE[32420] logger.c:    Timestamp: 1288490670ms  SCall: 00003  DCall: 00002 [196.22.2.194:4569]
Jul 19 17:05:05 VERBOSE[32420] logger.c: Rx-Frame Retry[ No] -- OSeqno: 005 ISeqno: 002 Type: VOICE   Subclass: 138
Jul 19 17:05:05 VERBOSE[32420] logger.c:    Timestamp: 858994020ms  SCall: 00003  DCall: 00002 [196.22.2.194:4569]

And so it goes on.  the jitter buffer valiantly tries to make something of it, but needless to say fails.

I did a "cvs update -r 1.319 chan_iax2.c" to get the chan_iax2.c without all the timestamp calc changes, and this problem goes away.

Note that if the peer doesn't use the jitter buffer, these crazy timestamps probably won't have any particular effect.

But if they do, then your calls are toast.

Regards,
Steve
Comments:By: Kevin P. Fleming (kpfleming) 2005-07-19 19:25:48

This problem has disappeared from my system after applying the patch from ASTERISK-4704746. Please retest, and reopen the bug if it's still present on yours.
By: Steve Davies . (stevedavies) 2005-07-20 04:31:49

Hi,

I retested with todays most recent CVS which includes the little fix from ASTERISK-4624.

I still have the problem with outbound timestamps.

I've captured the IAX packet flow - this time on the problem machine itself.  I'll upload that packet trace as an attachment.

The call will be iLBC.

Steve
By: Steve Davies . (stevedavies) 2005-07-20 16:47:16

OK: I've figured out the cause.

in chan_iax2.c, calc_timestamp uses ast_samp2tv in the process of tweaking the p->offset for the call.  The offset is tweaked back and forth to try to keep predicted timestamps reasonably close to the actual clock.

Here's the code snippet:

                               p->offset = ast_tvadd(p->offset,
                                               ast_samp2tv((ms - p->nextpred)/10, 1000)); /* XXX what scale is this ??? */


So - the "sample" value passed to ast_samp2tv can be negative or positive.

But, ast_samp2tv was changed from having signed to unsigned parameters, in an attempt to fix the "warning negative timestamps" coming out of chan_sip.  This was in bug 4730.

So - our slightly negative "sample" value arrives in ast_samp2tv and is intepretted as a large positive, radically moving our offset and completely messing up the timestamp.

I'll make a patch in the morning - the fix could probably be any of:

 1) don't use ast_samp2tv in this case - revert to the previous "add_ms" function, or
 2) change ast_samp2tv back to signed parameters and look for another fix for the sip problem
 3) change ast_samp2tv to some long long signed format?

I currently did (1) in my source and the problem is gone (and this change is guaranteed not to effect chan_sip or other users of ast_samp2tv).

Regards,
Steve
By: Kevin P. Fleming (kpfleming) 2005-07-20 18:08:21

I'll take care of it shortly, thanks for the detailed debugging.
By: Kevin P. Fleming (kpfleming) 2005-07-20 18:40:35

OK, this is really, truly fixed now. I also added an explicit comment so that people will at least know that the math is being done in a little bit unusual way; hopefully stevek or one of the other jitter buffer gurus can add some explanatory text there.
By: Digium Subversion (svnbot) 2008-01-15 15:42:09.000-0600

Repository: asterisk
Revision: 6180

U   trunk/channels/chan_iax2.c

------------------------------------------------------------------------
r6180 | kpfleming | 2008-01-15 15:42:09 -0600 (Tue, 15 Jan 2008) | 2 lines

_really_ fix IAX2 crazy timestamp problem (bug ASTERISK-4626)

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

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