[Home]

Summary:ASTERISK-16154: [patch] [regression] audio delay when bridging calls related to timestamp mismatch
Reporter:sdolloff (sdolloff)Labels:
Date Opened:2010-05-26 11:55:31Date Closed:2011-07-26 11:39:20
Priority:MajorRegression?Yes
Status:Closed/CompleteComponents:Core/RTP
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) 0526console.txt
( 1) bug17007-14.patch
( 2) bug17404.patch
( 3) dlstest2_0526-4.pcap
( 4) noc-drd-695.pcap
( 5) valgrind.txt
Description:when answering an inbound call, the remote party hears a delay from 1-3 seconds.  The audio is being transmitted, but the rtp timestamps take a huge jump when the call is answered even though the rtp sequencing is correct.
This started occurring after 1.4.28.  reproduced with 1.4.30, 1.4.32 and SVN from 05/25/2010.  This has been reproduced on multiple servers with multiple handsets and multiple remote endpoints.  

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

attaching valgrind output, local pcap, remote pcap for 3 calls.  rtp and sip debug for last call.  The audio on the captures sounds fine, but the analysis thinks there is jitter because of the timestamp discrepancy.  Also there is an rtp marker set at the point of the jitter in each call.

possible related unresolved reports:
https://issues.asterisk.org/view.php?id=16941
https://issues.asterisk.org/view.php?id=15824
Comments:By: sdolloff (sdolloff) 2010-05-26 12:00:56

in dlstest2_0526-4.pcap, if you look at the rtp stream sourcing from 209.242.51.5 11314 destination 209.242.32.134 16010 you will see at packet 4157, sequence number 9073 the jitter goes from .018 to 25381.99 ms and stays there.


By: sdolloff (sdolloff) 2010-05-26 12:11:12

reproduced on Centos 5.2 and 5.4
By: sdolloff (sdolloff) 2010-06-25 15:35:19

i just reproduced this timing behavior with 1.6.2.9
By: sdolloff (sdolloff) 2010-07-01 16:37:46

this seems related to this bug. https://issues.asterisk.org/view.php?id=17007
By: Jeff Peeler (jpeeler) 2010-07-29 17:49:27

Before I dive into this issue, I'm curious if the patch posted on 17007 about a week ago was tried.
By: sdolloff (sdolloff) 2010-07-30 15:23:57

not by me.  i'm not sure where to get the patches, which patch to use (there are multiple ones referenced), or which branch of the code said patch should be applied to.
By: Jeff Peeler (jpeeler) 2010-08-03 12:31:47

Try the patch I attached which applies to the latest 1.4.
By: sdolloff (sdolloff) 2010-08-03 15:52:36

tried the patch with 1.4.35-rc1.  skew of 220612448 ms still occurs on the rtp stream from the pbx to the source of the call when answered by a handset
By: Jeff Peeler (jpeeler) 2010-08-10 12:48:13

So all that's being done to reproduce this issue is answer an incoming call?
By: sdolloff (sdolloff) 2010-08-10 13:34:05

i stripped my dialplan down to just a background and dial exten and the problem doesn't exist, so I will isolate what part of the dialplan is causing the issue and update
By: Jeff Peeler (jpeeler) 2010-08-10 13:35:11

Thanks for narrowing it down, update as soon as you can.
By: sdolloff (sdolloff) 2010-08-10 16:32:18

the failure to reproduce the jitter with a stripped dialplan was a fluke.  it happens almost every time.  here is the dialplan i'm using for testing.  the easiest way to identify the problem is that in 1.4.28, after the handset answers, there is a new SSRC for the outbound RTP stream.  with 1.4.35, it continues to use the same SSRC.

[prepincoming]
exten => 999,1,Answer
exten => 999,2,Background(hpbx/1)
exten => 999,3,Goto(prepincoming,999,2)
exten => 103,1,Dial(SIP/103)
By: Jeff Peeler (jpeeler) 2010-08-10 18:10:26

It appears that this change was intentional (https://reviewboard.asterisk.org/r/540). Will continue to investigate.
By: Jeff Peeler (jpeeler) 2010-08-11 11:48:09

I believe the uploaded patch will solve the problem for you, although more changes may be required.
By: sdolloff (sdolloff) 2010-08-11 16:11:57

this patch solves the jitter and skew that I was seeing.  max jitter is now 4ms.  no discernable audio loss.


By: Digium Subversion (svnbot) 2010-08-11 22:00:14

Repository: asterisk
Revision: 281911

U   branches/1.4/main/channel.c

------------------------------------------------------------------------
r281911 | jpeeler | 2010-08-11 22:00:12 -0500 (Wed, 11 Aug 2010) | 20 lines

Ensure SSRC is changed when media source is changed to resolve audio delay.

This change causes the SSRC to change right before the channels are bridged,
which is what used to happen. It seems that fixes were made to attempt limiting
SSRC changes, targeted mainly at sending DTMF. DTMF is not affecting the SSRC
with this change.

There are two other control frames sent in ast_channel_bridge that probably
should also be changed to AST_CONTROL_SRCCHANGE as well, but I'm going to leave
this change up to the discretion of resolving issue ASTERISK-15790.

For reference - old review implementing new control frame SRCCHANGE:
https://reviewboard.asterisk.org/r/540

(closes issue ASTERISK-16154)
Reported by: sdolloff
Patches:
     bug17404.patch uploaded by jpeeler (license 325)
Tested by: sdolloff

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

http://svn.digium.com/view/asterisk?view=rev&revision=281911
By: Digium Subversion (svnbot) 2010-08-11 22:01:38

Repository: asterisk
Revision: 281912

_U  branches/1.6.2/
U   branches/1.6.2/main/channel.c

------------------------------------------------------------------------
r281912 | jpeeler | 2010-08-11 22:01:36 -0500 (Wed, 11 Aug 2010) | 27 lines

Merged revisions 281911 via svnmerge from
https://origsvn.digium.com/svn/asterisk/branches/1.4

........
 r281911 | jpeeler | 2010-08-11 22:00:14 -0500 (Wed, 11 Aug 2010) | 20 lines
 
 Ensure SSRC is changed when media source is changed to resolve audio delay.
 
 This change causes the SSRC to change right before the channels are bridged,
 which is what used to happen. It seems that fixes were made to attempt limiting
 SSRC changes, targeted mainly at sending DTMF. DTMF is not affecting the SSRC
 with this change.
 
 There are two other control frames sent in ast_channel_bridge that probably
 should also be changed to AST_CONTROL_SRCCHANGE as well, but I'm going to leave
 this change up to the discretion of resolving issue ASTERISK-15790.
 
 For reference - old review implementing new control frame SRCCHANGE:
 https://reviewboard.asterisk.org/r/540
 
 (closes issue ASTERISK-16154)
 Reported by: sdolloff
 Patches:
       bug17404.patch uploaded by jpeeler (license 325)
 Tested by: sdolloff
........

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

http://svn.digium.com/view/asterisk?view=rev&revision=281912
By: Digium Subversion (svnbot) 2010-08-11 22:03:37

Repository: asterisk
Revision: 281913

_U  branches/1.8/
U   branches/1.8/main/channel.c

------------------------------------------------------------------------
r281913 | jpeeler | 2010-08-11 22:03:36 -0500 (Wed, 11 Aug 2010) | 34 lines

Merged revisions 281912 via svnmerge from
https://origsvn.digium.com/svn/asterisk/branches/1.6.2

................
 r281912 | jpeeler | 2010-08-11 22:01:38 -0500 (Wed, 11 Aug 2010) | 27 lines
 
 Merged revisions 281911 via svnmerge from
 https://origsvn.digium.com/svn/asterisk/branches/1.4
 
 ........
   r281911 | jpeeler | 2010-08-11 22:00:14 -0500 (Wed, 11 Aug 2010) | 20 lines
   
   Ensure SSRC is changed when media source is changed to resolve audio delay.
   
   This change causes the SSRC to change right before the channels are bridged,
   which is what used to happen. It seems that fixes were made to attempt limiting
   SSRC changes, targeted mainly at sending DTMF. DTMF is not affecting the SSRC
   with this change.
   
   There are two other control frames sent in ast_channel_bridge that probably
   should also be changed to AST_CONTROL_SRCCHANGE as well, but I'm going to leave
   this change up to the discretion of resolving issue ASTERISK-15790.
   
   For reference - old review implementing new control frame SRCCHANGE:
   https://reviewboard.asterisk.org/r/540
   
   (closes issue ASTERISK-16154)
   Reported by: sdolloff
   Patches:
         bug17404.patch uploaded by jpeeler (license 325)
   Tested by: sdolloff
 ........
................

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

http://svn.digium.com/view/asterisk?view=rev&revision=281913
By: Digium Subversion (svnbot) 2010-08-11 22:08:46

Repository: asterisk
Revision: 281914

_U  trunk/
U   trunk/main/channel.c

------------------------------------------------------------------------
r281914 | jpeeler | 2010-08-11 22:08:44 -0500 (Wed, 11 Aug 2010) | 41 lines

Merged revisions 281913 via svnmerge from
https://origsvn.digium.com/svn/asterisk/branches/1.8

................
 r281913 | jpeeler | 2010-08-11 22:03:37 -0500 (Wed, 11 Aug 2010) | 34 lines
 
 Merged revisions 281912 via svnmerge from
 https://origsvn.digium.com/svn/asterisk/branches/1.6.2
 
 ................
   r281912 | jpeeler | 2010-08-11 22:01:38 -0500 (Wed, 11 Aug 2010) | 27 lines
   
   Merged revisions 281911 via svnmerge from
   https://origsvn.digium.com/svn/asterisk/branches/1.4
   
   ........
     r281911 | jpeeler | 2010-08-11 22:00:14 -0500 (Wed, 11 Aug 2010) | 20 lines
     
     Ensure SSRC is changed when media source is changed to resolve audio delay.
     
     This change causes the SSRC to change right before the channels are bridged,
     which is what used to happen. It seems that fixes were made to attempt limiting
     SSRC changes, targeted mainly at sending DTMF. DTMF is not affecting the SSRC
     with this change.
     
     There are two other control frames sent in ast_channel_bridge that probably
     should also be changed to AST_CONTROL_SRCCHANGE as well, but I'm going to leave
     this change up to the discretion of resolving issue ASTERISK-15790.
     
     For reference - old review implementing new control frame SRCCHANGE:
     https://reviewboard.asterisk.org/r/540
     
     (closes issue ASTERISK-16154)
     Reported by: sdolloff
     Patches:
           bug17404.patch uploaded by jpeeler (license 325)
     Tested by: sdolloff
   ........
 ................
................

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

http://svn.digium.com/view/asterisk?view=rev&revision=281914
By: Jeff Peeler (jpeeler) 2010-12-07 16:17:15.000-0600

I'm afraid this needs to be reopened as this fix very much affects the SSRC when DTMF is processed. I was never able to reproduce the delay problems though. sdolloff I hope that you're still around and we can find another fix.
By: Jeff Peeler (jpeeler) 2010-12-07 16:43:33.000-0600

I believe the problem here may have been caused by a Sonus switch, please look at 15642. I'm going to revert the change here as it is just plain wrong.
By: Digium Subversion (svnbot) 2010-12-07 16:57:49.000-0600

Repository: asterisk
Revision: 297823

U   branches/1.4/main/channel.c

------------------------------------------------------------------------
r297823 | jpeeler | 2010-12-07 16:57:48 -0600 (Tue, 07 Dec 2010) | 12 lines

Revert code that changed SSRC for DTMF.

Some previous behavior was attempted to be restored, but mistakingly I did
not realize that the previous behavior was incorrect. This fixes DTMF not
being detected since DTMF shouldn't cause the SSRC to change.

(related to issue ASTERISK-16154)
(closes issue ASTERISK-16851)
(closes issue ASTERISK-17001)
Reported by: marcbou
Tested by: cmbaker82

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

http://svn.digium.com/view/asterisk?view=rev&revision=297823
By: Digium Subversion (svnbot) 2010-12-07 16:58:55.000-0600

Repository: asterisk
Revision: 297824

_U  branches/1.6.2/
U   branches/1.6.2/main/channel.c

------------------------------------------------------------------------
r297824 | jpeeler | 2010-12-07 16:58:55 -0600 (Tue, 07 Dec 2010) | 19 lines

Merged revisions 297823 via svnmerge from
https://origsvn.digium.com/svn/asterisk/branches/1.4

........
 r297823 | jpeeler | 2010-12-07 16:57:48 -0600 (Tue, 07 Dec 2010) | 12 lines
 
 Revert code that changed SSRC for DTMF.
 
 Some previous behavior was attempted to be restored, but mistakingly I did
 not realize that the previous behavior was incorrect. This fixes DTMF not
 being detected since DTMF shouldn't cause the SSRC to change.
 
 (related to issue ASTERISK-16154)
 (closes issue ASTERISK-16851)
 (closes issue ASTERISK-17001)
 Reported by: marcbou
 Tested by: cmbaker82
........

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

http://svn.digium.com/view/asterisk?view=rev&revision=297824
By: Digium Subversion (svnbot) 2010-12-07 16:59:31.000-0600

Repository: asterisk
Revision: 297825

_U  branches/1.8/
U   branches/1.8/main/channel.c

------------------------------------------------------------------------
r297825 | jpeeler | 2010-12-07 16:59:30 -0600 (Tue, 07 Dec 2010) | 26 lines

Merged revisions 297824 via svnmerge from
https://origsvn.digium.com/svn/asterisk/branches/1.6.2

................
 r297824 | jpeeler | 2010-12-07 16:58:54 -0600 (Tue, 07 Dec 2010) | 19 lines
 
 Merged revisions 297823 via svnmerge from
 https://origsvn.digium.com/svn/asterisk/branches/1.4
 
 ........
   r297823 | jpeeler | 2010-12-07 16:57:48 -0600 (Tue, 07 Dec 2010) | 12 lines
   
   Revert code that changed SSRC for DTMF.
   
   Some previous behavior was attempted to be restored, but mistakingly I did
   not realize that the previous behavior was incorrect. This fixes DTMF not
   being detected since DTMF shouldn't cause the SSRC to change.
   
   (related to issue ASTERISK-16154)
   (closes issue ASTERISK-16851)
   (closes issue ASTERISK-17001)
   Reported by: marcbou
   Tested by: cmbaker82
 ........
................

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

http://svn.digium.com/view/asterisk?view=rev&revision=297825
By: Digium Subversion (svnbot) 2010-12-07 17:00:43.000-0600

Repository: asterisk
Revision: 297826

_U  trunk/
U   trunk/main/channel.c

------------------------------------------------------------------------
r297826 | jpeeler | 2010-12-07 17:00:42 -0600 (Tue, 07 Dec 2010) | 33 lines

Merged revisions 297825 via svnmerge from
https://origsvn.digium.com/svn/asterisk/branches/1.8

................
 r297825 | jpeeler | 2010-12-07 16:59:30 -0600 (Tue, 07 Dec 2010) | 26 lines
 
 Merged revisions 297824 via svnmerge from
 https://origsvn.digium.com/svn/asterisk/branches/1.6.2
 
 ................
   r297824 | jpeeler | 2010-12-07 16:58:54 -0600 (Tue, 07 Dec 2010) | 19 lines
   
   Merged revisions 297823 via svnmerge from
   https://origsvn.digium.com/svn/asterisk/branches/1.4
   
   ........
     r297823 | jpeeler | 2010-12-07 16:57:48 -0600 (Tue, 07 Dec 2010) | 12 lines
     
     Revert code that changed SSRC for DTMF.
     
     Some previous behavior was attempted to be restored, but mistakingly I did
     not realize that the previous behavior was incorrect. This fixes DTMF not
     being detected since DTMF shouldn't cause the SSRC to change.
     
     (related to issue ASTERISK-16154)
     (closes issue ASTERISK-16851)
     (closes issue ASTERISK-17001)
     Reported by: marcbou
     Tested by: cmbaker82
   ........
 ................
................

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

http://svn.digium.com/view/asterisk?view=rev&revision=297826
By: sdolloff (sdolloff) 2010-12-07 17:04:53.000-0600

I am still around and this will still be a problem.
By: Russell Bryant (russell) 2010-12-14 10:29:38.000-0600

sdolloff - please take a look at ASTERISK-14589 and see if the patch there fixes your problem.
By: sdolloff (sdolloff) 2011-01-19 10:49:41.000-0600

i checked both patches from that bug and neither of them resolved the timestamp discrepancy.  in version 1.6.2.16.1, wireshark indicates jitter on the call leg (6000-20000ms) sourcing from asterisk between asterisk and the remote media gateway when the call originates from the lvl3 media gateway. level3 sees the same jitter and claims that this interferes with their jitter buffers. this was not the case before this patch was reverted.
By: Olle Johansson (oej) 2011-01-27 05:52:21.000-0600

I have noticed this bug on calls that are coming in from a SIP trunk to Asterisk A, then forwarded to Asterisk B after playing some prompts in Asterisk A.
By: Chris Baker (cmbaker82) 2011-01-27 07:30:28.000-0600

We are only using SIP trunks, but have only one Asterisk server and are experiencing the delay
By: B VELUET (bveluet) 2011-02-21 09:55:22.000-0600

sdolloff you said "This started occurring after 1.4.28. reproduced with 1.4.30, 1.4.32 and SVN from 05/25/2010."
Does it mean that with 1.4.27 or 1.4.28 you have no issue ?
By: sdolloff (sdolloff) 2011-02-21 10:37:08.000-0600

i didn't run with 1.4.27 or 1.4.29, but the issue does not occur in 1.4.28.  It also does not occur in 1.4.36. (1.4.36 is the version that included the patch to revert the changes that happened after 1.4.28.  This patch was then re-reverted after 1.4.36 so now it's broken again)
By: Russell Bryant (russell) 2011-07-26 11:38:39.436-0500

Per the Asterisk maintenance timeline page at http://www.asterisk.org/asterisk-versions maintenance (bug) support for the 1.4 and 1.6.x branches has ended. For continued maintenance support please move to the 1.8 branch which is a long term support (LTS) branch. For more information about branch support, please see https://wiki.asterisk.org/wiki/display/AST/Asterisk+Versions