[Asterisk-Dev] iax2 bridge optimization screwing with timestamps

[Andrew Kohlsmith]

Steve Kann and myself were working on the new packet loss concealing jitter 
buffer today and we ran across a (potential?) bug in the iax2 bridge 
optimization code.  I'm soliciting comments before I open a bug, since the 
bug marshals seem a little overzealous at times.  :-)

Normal frames are 20ms long and are sent out as such.  The timestamps on the 
outgoing iax2 packets are lock-step 20ms apart.  e.g.

0 20 40 60 80 100 120 140 160 180 200 220 240 260 280...

However if you have an asterisk box (all tested with todays CVS HEAD) in the 
middle and it's natively bridging you will see the actual timestamps inside 
the packets look like this periodically.  Sending DTMF seems to really 
aggravate it, although it does occur on its own:

0 20 40 60 80 81 82 83 84 180 200 220 221 260 280...

The same number of packets, and physically they're sent out at the right times 
(i.e. packet capture timestamps are showing ~20ms between UDP packets).  It 
is also curious to note that the original timestamps aren't "lost" -- they're 
just replaced with lastframets+1 on occassion, sometimes for runs as long as 
8 or 9 packets I've seen.

This seems to occur only when bridge optimization is used, in the 
calc_fakestamp() function:

/* FIXME? SLD would rather remove this and leave it to the end system to deal 
with */
if (fakets <= p2->lastsent)
  fakets = p2->lastsent + 1;
p2->lastsent = fakets;

Now this isn't intuitive to me -- What exactly is this code fragment trying to 
do, and why on earth would you send it as the lastpacket+1 when it's supposed 
to be 20ms (or more generally, a codec frametime) later?

I was more or less able to compensate for it with the following code near the 
end of schedule_delivery():

if(fr->af.frametype == AST_FRAME_VOICE) {
  type = JB_TYPE_VOICE;
  len = get_samples(&fr->af)/8;

  if(fr->ts < iaxs[fr->callno]->last_real_ts + ((len / 2)+1)) {
    iaxs[fr->callno]->num_fake_ts++;
    fr->ts = iaxs[fr->callno]->last_real_ts + (iaxs[fr->callno]->num_fake_ts * 
len) - 1;
  } else {
    iaxs[fr->callno]->last_real_ts = fr->ts;
    iaxs[fr->callno]->num_fake_ts = 0;
  }

What it does is rewrite the frame's timestamp if the frame comes in and it has 
a timestamp that is closer to the last timestamp than it is to what the next 
timestamp should be.  Obviously this is a band-aid solution and in 
practicality it works moderately well, but not perfectly.

If I undefine/comment out BRIDGE_OPTIMIZATION in chan_iax2.c the problem goes 
away completely and my received frame timestamps are not screwed with but I 
am not sure what this means in terms of chan_iax2 in general.

Can someone assist me in understanding this?  The new packet-loss-concealing 
jitter buffer completely barfs on this kind of timestamp stream, like because 
(as stevekstevek put it) it gets a packet with timestamp n, then gets a 
packet for timestamp n+1, only it's 20ms later and hterefore declares the 
packet late and drops it, as it's claiming to be for timestamp n+1 when the 
jitter buffer's working on timestamp n+20 now.

The old (current) jitter buffer doesn't seem to have an issue with this but, 
then again, the current system is timed from the received stream to begin 
with.

-A.