Summary:ASTERISK-01188: Timestamp Problems on the RTP Stream
Reporter:Ricardo Villa (ricvil)Labels:
Date Opened:2004-03-09 23:45:13.000-0600Date Closed:2004-09-25 02:54:39
Versions:Frequency of
Environment:Attachments:( 0) asterisk_bad_timestamp
Description:We have identified an issue with Asterisk generated RTP Streams.  Most notably seen when a local SIP phone dials out to a remote SIP phone over a WAN link.  The RTP Timestamp is not generated properly by Asterisk.


This is the test setup.  One SIP phone on the LAN registered locally with Asterisk.  And one remote SIP phone registered over the WAN Link.  Both SIP phones start a conversation and all is well.  Then we generate more and more traffic on the WAN Link until packets start arriving "out-of-sequence" on the WAN Link.  

Asterisk is able to "re-order" the packets correctly but when it sends them out on the LAN side it only fixes the RTP sequence number but not the RTP Timestamp.  This results in degraded audio on the LAN side, even though RTP analysis shows 0% packet loss.  The problem is that the decoder on the Hardphone (SPA2000) sees the bad Timestamps and interprets that as missed frames.  This was tested on both G711 and G729 with both transcoding and passthrough with equal results.

The attached Ethereal trace shows such a call.  If you detail frames 4-12 you see how all frames differ by 160.  But between frames 12-13 there is a jump of 1056.  All the packets have contiguous sequence numbers.  There are no packets lost since all the sequence numbers are there.

But the Audio is degraded.  This case was first sent to Sipura for analysis and this is what they had to say:  "
I know there is NO frames lost, based on the sequence number.
But some timestamp are missing; those are gaps or lost frames.
If you think the Asterisk does not have silence suppression, then how do you explain the missing timestamps.
The SPA honors the time-stamps and tries to insert the
Notice that the time-stamps are also used for
timing synchronization and jitter measurements."

Can somebody please take a look at the code and see if it can be fixed?  

The TimeStamp is there for a reason and if Asterisk is able to re-order the out-of-sequence incoming packets then it should also be able to reorder or regenerate a fresh new TimeStamp.

Comments:By: Ricardo Villa (ricvil) 2004-03-11 01:21:38.000-0600

I continued testing this all day.  The problem manifests itself even when all packets recevied on the WAN side are in the correct sequence.  Enabling the DEBUG on the console revealed some messages that coincided with the bad TimeStamp on the RTP Packets.  This is the common message:

rtp.c:950 ast_rtp_raw_write: Difference is 720, ms is 110

Looking at the rtp.c code it revealed the part where it calculates the TimeStamp:

             /* If it's close to our prediction, go for it */
               if (abs(rtp->lastts - pred) < 640)
                       rtp->lastts = pred;
                       ast_log(LOG_DEBUG, "Difference is %d, ms is %d\n", abs(rtp->lastts - pred), ms);

So it appears that if Asterisk sees an RTP packet with a greater delay(from the expected value) than 640 (64ms), then it recalculates the TimeStamp and Logs the Message.  But the effect of this on an SPA2000 is that it sees the wrong TimeStamp and assumes a big chunk of RTP packets were lost.  With an Ethereal trace I confirmed exactly that this happens when there is a large delay between one RTP packet and the next on the incoming WAN side (in my case just a delay of 100ms from the expected arrival, causes Asterisk to mess the TimeStamp up).

So my simple fix was to increase that value from 640 to 2560.  This will allow packets with a delay of up to 256ms (which can happen from time to time during a conversation) to not mess up Asterisk.  I tested this change and the difference was night and day.  Now we can carry a normal conversation with the SPA2000 that feels like we are on a land line instead of a cell phone.

Maybe someone can make this a config option.

This BUG can be closed now.

By: Mark Spencer (markster) 2004-03-14 16:10:38.000-0600

Timestamps in CVS *head* (not stable) should be much better, as they will now get carried through asterisk.

By: Mark Spencer (markster) 2004-03-14 16:11:01.000-0600

Fixed in -devel.