[Home]

Summary:ASTERISK-05852: when jitterbuffer=yes DTMF is unreliable on IAX2 links
Reporter:Chip Schweiss (lschweiss)Labels:
Date Opened:2005-12-15 15:51:10.000-0600Date Closed:2006-09-27 13:52:41
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Channels/chan_iax2
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) asterisk.log
( 1) asterisk2.log
( 2) baddtmf-pri.tar.bz2
( 3) jitter.txt
( 4) trace.txt
( 5) traceroute.log
Description:When jitterbuffer is enabled only about 1/2 my calls get a response to DTMF.  I've ran iax2 debug and I can clearly see the DTMF codes coming through but Asterisk is not responding to them.

It is either all or nothing on a per call basis.

If jitterbuffer is set to off, DTMF seems to work all the time.  At least I haven't been able to trip it yet.

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

I'm running Asterisk 1.2.1 as downloaded from asterisk.org on SuSE 10.0.  The problem is the same on two different * boxes with the same version and OS.  

Here's my iax2 debug output when it is not working:

Rx-Frame Retry[ No] -- OSeqno: 006 ISeqno: 004 Type: DTMF    Subclass: #
  Timestamp: 03772ms  SCall: 00029  DCall: 00001 [208.139.204.228:4569]
Tx-Frame Retry[-01] -- OSeqno: 004 ISeqno: 007 Type: IAX     Subclass: ACK
  Timestamp: 03772ms  SCall: 00001  DCall: 00029 [208.139.204.228:4569]
Rx-Frame Retry[ No] -- OSeqno: 007 ISeqno: 004 Type: VOICE   Subclass: 2
  Timestamp: 3758100149ms  SCall: 00029  DCall: 00001 [208.139.204.228:4569]
Tx-Frame Retry[-01] -- OSeqno: 004 ISeqno: 008 Type: IAX     Subclass: ACK
  Timestamp: 3758100149ms  SCall: 00001  DCall: 00029 [208.139.204.228:4569]
Rx-Frame Retry[ No] -- OSeqno: 008 ISeqno: 004 Type: DTMF    Subclass: #
  Timestamp: 04851ms  SCall: 00029  DCall: 00001 [208.139.204.228:4569]
Tx-Frame Retry[-01] -- OSeqno: 004 ISeqno: 009 Type: IAX     Subclass: ACK
  Timestamp: 04851ms  SCall: 00001  DCall: 00029 [208.139.204.228:4569]
Rx-Frame Retry[ No] -- OSeqno: 009 ISeqno: 004 Type: VOICE   Subclass: 2
  Timestamp: 3758101229ms  SCall: 00029  DCall: 00001 [208.139.204.228:4569]
Tx-Frame Retry[-01] -- OSeqno: 004 ISeqno: 010 Type: IAX     Subclass: ACK
  Timestamp: 3758101229ms  SCall: 00001  DCall: 00029 [208.139.204.228:4569]
Rx-Frame Retry[ No] -- OSeqno: 010 ISeqno: 004 Type: DTMF    Subclass: #
  Timestamp: 05629ms  SCall: 00029  DCall: 00001 [208.139.204.228:4569]
Tx-Frame Retry[-01] -- OSeqno: 004 ISeqno: 011 Type: IAX     Subclass: ACK
  Timestamp: 05629ms  SCall: 00001  DCall: 00029 [208.139.204.228:4569]
Comments:By: James Lyons (james) 2006-01-27 15:16:12.000-0600

Can you provide a detailed console output of this occuring? Also are the calls coming from a remote location or are they generated internally or does it matter?

By: stevekstevek (stevekstevek) 2006-01-27 15:34:51.000-0600

The timestamps on those full voice frames look..  err.. interesting:

3758100149ms is probably an error somewhere..

By: Chip Schweiss (lschweiss) 2006-01-27 16:00:46.000-0600

The call that I took that output from was through Teliax.  So yes a remote location.  I haven't tried anything local.  The Asterisk box is behind a NAT router, but I don't think that could have anything to do with this problem.  

I had verbosity at 4 when running iax2 dubug on the console to generate the output above.  I'm not aware how to get more detailed information out of it.

By: Olle Johansson (oej) 2006-01-30 14:05:05.000-0600

Any updates to this issue?

/Housekeeping

By: Mark Hulber (hulber) 2006-02-03 13:00:38.000-0600

I was having a problem with "Junction Networks" on a new IAX DID and found this bug.  As soon as I turned off the jitterbuffer I received DTMF OK.  With Teliax I don't have this problem.

Debug output with Jitterbuffer and No DTMF:

Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: DTMF    Subclass: 5
  Timestamp: 07003ms  SCall: 00021  DCall: 00006 [66.227.100.34:4569]
Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 002 Type: IAX     Subclass: ACK    
  Timestamp: 07003ms  SCall: 00006  DCall: 00021 [66.227.100.34:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 001 Type: DTMF    Subclass: 5
  Timestamp: 07483ms  SCall: 00021  DCall: 00006 [66.227.100.34:4569]
Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 003 Type: IAX     Subclass: ACK    


Without Jitterbuffer and OK DTMF:

Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: DTMF    Subclass: 6
  Timestamp: 04563ms  SCall: 00031  DCall: 00007 [66.227.100.34:4569]
Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 002 Type: IAX     Subclass: ACK    
  Timestamp: 04563ms  SCall: 00007  DCall: 00031 [66.227.100.34:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 001 Type: DTMF    Subclass: 6
  Timestamp: 05003ms  SCall: 00031  DCall: 00007 [66.227.100.34:4569]
Tx-Frame Retry[-01] -- OSeqno: 001 ISeqno: 003 Type: IAX     Subclass: ACK    
  Timestamp: 05003ms  SCall: 00007  DCall: 00031 [66.227.100.34:4569]

They look about the same to me.

asterisk*CLI> show version
Asterisk SVN-trunk-r9013M built by root @ asterisk.hulber.com on a i686 running Linux on 2006-02-01 04:56:57 UTC

By: Mark Hulber (hulber) 2006-02-03 13:08:47.000-0600

With Teliax the output looks different.  This is with Jitterbuffer on and OK DTMF:

Rx-Frame Retry[ No] -- OSeqno: 007 ISeqno: 005 Type: IAX     Subclass: ACK    
  Timestamp: 14803ms  SCall: 00162  DCall: 00014 [66.246.220.19:4569]
Feb  3 14:48:53 WARNING[22610]: chan_iax2.c:695 jb_warning_output: Resyncing the jb. last_delay 0, this delay -4804, threshold 1000, new offset 4804
Tx-Frame Retry[000] -- OSeqno: 005 ISeqno: 007 Type: DTMF    Subclass: 6
  Timestamp: 10027ms  SCall: 00014  DCall: 00162 [66.246.220.19:4569]
Rx-Frame Retry[ No] -- OSeqno: 007 ISeqno: 006 Type: IAX     Subclass: ACK    
  Timestamp: 10027ms  SCall: 00162  DCall: 00014 [66.246.220.19:4569]
Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 004 Type: DTMF    Subclass: 6
  Timestamp: 03743ms  SCall: 00318  DCall: 00015 [208.139.204.245:4569]
Tx-Frame Retry[-01] -- OSeqno: 004 ISeqno: 004 Type: IAX     Subclass: ACK    
  Timestamp: 03743ms  SCall: 00015  DCall: 00318 [208.139.204.245:4569]
Feb  3 14:48:54 WARNING[22610]: chan_iax2.c:695 jb_warning_output: Resyncing the jb. last_delay 0, this delay -4803, threshold 1000, new offset 4803
Tx-Frame Retry[000] -- OSeqno: 006 ISeqno: 007 Type: DTMF    Subclass: 6
  Timestamp: 10728ms  SCall: 00014  DCall: 00162 [66.246.220.19:4569]
Rx-Frame Retry[ No] -- OSeqno: 007 ISeqno: 007 Type: IAX     Subclass: ACK    
  Timestamp: 10728ms  SCall: 00162  DCall: 00014 [66.246.220.19:4569]
Rx-Frame Retry[ No] -- OSeqno: 004 ISeqno: 004 Type: DTMF    Subclass: 6
  Timestamp: 04303ms  SCall: 00318  DCall: 00015 [208.139.204.245:4569]
Tx-Frame Retry[-01] -- OSeqno: 004 ISeqno: 005 Type: IAX     Subclass: ACK    
  Timestamp: 04303ms  SCall: 00015  DCall: 00318 [208.139.204.245:4569]

By: mjc (mjc) 2006-02-27 07:04:14.000-0600

I have the same problem with v1.2.4, using exgn.net as an IAX provider. On some calls, DTMF will not work at all if jitterbuffer=on. However, it works just fine under all conditions with another IAX provider (Unlimitel.ca).

By: Joshua M. Thompson (secure24) 2006-02-28 09:25:44.000-0600

I think this is relatd to an issue I am having as well. What's strange is things seemed to be working fine for me up until a few days ago. Basically what I'm seeing is that when you call our number and get to the IVR you can't dial any multi-digit options. It will sit and wait for you to dial but time out and only accept the first digit you dialed. Calling the IVR locally from a SIP phone works 100% of the time. Calling remotely through IAX2 is sporadic at best and jitterbuffer=yes/no does not seem to make any noticable difference.

This box runs 1.2.4 and talks to NuFone. I also see it calling from my house (running current SVN), through an intermediate 1.2.4 box to our box (end-to-end digital, SIP => IAX2 => IAX2).

Running iax2 debug output is very strange. I clearly see the first digit received and ACKed, but when it doesn't work the subsequent digits just don't show up at all, almost as if they aren't being sent.

By: Joshua M. Thompson (secure24) 2006-02-28 09:39:34.000-0600

here's a log of a failed call, with some interesting observations by me:

Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass: POKE
  Timestamp: 00002ms  SCall: 00006  DCall: 00000 [216.234.116.177:4569]
Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 001 Type: IAX     Subclass: PONG
  Timestamp: 00002ms  SCall: 00001  DCall: 00006 [216.234.116.177:4569]
Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: IAX     Subclass: ACK
  Timestamp: 00002ms  SCall: 00006  DCall: 00001 [216.234.116.177:4569]
Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX     Subclass: NEW
  Timestamp: 00006ms  SCall: 00664  DCall: 00000 [198.22.67.70:4569]
  VERSION         : 2
  CALLED NUMBER   : 8665551212
  CODEC_PREFS     : (ulaw|gsm|g726|ilbc|speex|adpcm|g723|g729|alaw)
  CALLING NUMBER  : 3135551212
  CALLING PRESNTN : 1
  CALLING TYPEOFN : 33
  CALLING TRANSIT : 0
  CALLING NAME    : Toll-Free Call
  LANGUAGE        : en
  USERNAME        : NuFone
  FORMAT          : 4
  CAPABILITY      : 65343
  ADSICPE         : 2
  DATE TIME       : 2006-02-28  11:34:52

Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 001 Type: IAX     Subclass: AUTHREQ
  Timestamp: 00017ms  SCall: 00002  DCall: 00664 [198.22.67.70:4569]
  AUTHMETHODS     : 3
  CHALLENGE       : xxxxxxxx
  USERNAME        : NuFone

Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: IAX     Subclass: AUTHREP
  Timestamp: 00021ms  SCall: 00664  DCall: 00002 [198.22.67.70:4569]
  MD5 RESULT      : d2bb15873d3ca2eedea966bff7adccee

   -- Accepting AUTHENTICATED call from 198.22.67.70:
      > requested format = ulaw,
      > requested prefs = (),
      > actual format = ulaw,
      > host prefs = (),
      > priority = mine
Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 002 Type: IAX     Subclass: ACCEPT
  Timestamp: 00031ms  SCall: 00002  DCall: 00664 [198.22.67.70:4569]
  FORMAT          : 4

   -- Executing Goto("IAX2/198.22.67.70:4569-2", "s24-main|s|1") in new stack
   -- Goto (s24-main,s,1)
   -- Executing Answer("IAX2/198.22.67.70:4569-2", "") in new stack
   -- Executing Wait("IAX2/198.22.67.70:4569-2", "1") in new stack
Tx-Frame Retry[000] -- OSeqno: 002 ISeqno: 002 Type: CONTROL Subclass: ANSWER
  Timestamp: 00034ms  SCall: 00002  DCall: 00664 [198.22.67.70:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: IAX     Subclass: ACK
  Timestamp: 00031ms  SCall: 00664  DCall: 00002 [198.22.67.70:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 003 Type: IAX     Subclass: ACK
  Timestamp: 00034ms  SCall: 00664  DCall: 00002 [198.22.67.70:4569]
Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 003 Type: VOICE   Subclass: 4
  Timestamp: 00060ms  SCall: 00664  DCall: 00002 [198.22.67.70:4569]
Tx-Frame Retry[-01] -- OSeqno: 003 ISeqno: 003 Type: IAX     Subclass: ACK
  Timestamp: 00060ms  SCall: 00002  DCall: 00664 [198.22.67.70:4569]
   -- Executing Set("IAX2/198.22.67.70:4569-2", "TIMEOUT(response)=20") in new stack
   -- Response timeout set to 20
   -- Executing BackGround("IAX2/198.22.67.70:4569-2", "s24-intro") in new stack
   -- Playing 's24-intro' (language 'en')
Tx-Frame Retry[000] -- OSeqno: 003 ISeqno: 003 Type: VOICE   Subclass: 4
  Timestamp: 01060ms  SCall: 00002  DCall: 00664 [198.22.67.70:4569]
Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 004 Type: IAX     Subclass: ACK
  Timestamp: 01060ms  SCall: 00664  DCall: 00002 [198.22.67.70:4569]
Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 004 Type: DTMF    Subclass: 8
  Timestamp: 03623ms  SCall: 00664  DCall: 00002 [198.22.67.70:4569]
Tx-Frame Retry[-01] -- OSeqno: 004 ISeqno: 004 Type: IAX     Subclass: ACK
  Timestamp: 03623ms  SCall: 00002  DCall: 00664 [198.22.67.70:4569]

(at this point Background() has paused the audio and is waiting for more digits, since all option 8 options are two digits long. I'm trying to hit "1" to invoke option 81 on the menu here but as you can see nothing is showing up...it eventually times out)

   -- Invalid extension '8' in context 's24-main' on IAX2/198.22.67.70:4569-2
 == CDR updated on IAX2/198.22.67.70:4569-2
   -- Executing Playback("IAX2/198.22.67.70:4569-2", "pbx-invalid") in new stack
   -- Playing 'pbx-invalid' (language 'en')

(ok now THIS is the freaky part. At this point the "pbx-invalid" message is still playing and I'm hitting the 1 key still and it's coming through every time!)

Rx-Frame Retry[ No] -- OSeqno: 004 ISeqno: 004 Type: DTMF    Subclass: 1
  Timestamp: 09843ms  SCall: 00664  DCall: 00002 [198.22.67.70:4569]
Tx-Frame Retry[-01] -- OSeqno: 004 ISeqno: 005 Type: IAX     Subclass: ACK
  Timestamp: 09843ms  SCall: 00002  DCall: 00664 [198.22.67.70:4569]
Tx-Frame Retry[000] -- OSeqno: 004 ISeqno: 005 Type: IAX     Subclass: LAGRQ
  Timestamp: 10039ms  SCall: 00002  DCall: 00664 [198.22.67.70:4569]
Rx-Frame Retry[ No] -- OSeqno: 005 ISeqno: 004 Type: IAX     Subclass: LAGRQ
  Timestamp: 10044ms  SCall: 00664  DCall: 00002 [198.22.67.70:4569]
Tx-Frame Retry[000] -- OSeqno: 005 ISeqno: 006 Type: IAX     Subclass: LAGRP
  Timestamp: 10044ms  SCall: 00002  DCall: 00664 [198.22.67.70:4569]
Rx-Frame Retry[ No] -- OSeqno: 006 ISeqno: 005 Type: IAX     Subclass: LAGRP
  Timestamp: 10039ms  SCall: 00664  DCall: 00002 [198.22.67.70:4569]
Tx-Frame Retry[-01] -- OSeqno: 005 ISeqno: 007 Type: IAX     Subclass: ACK
  Timestamp: 10039ms  SCall: 00002  DCall: 00664 [198.22.67.70:4569]
Rx-Frame Retry[ No] -- OSeqno: 006 ISeqno: 006 Type: IAX     Subclass: ACK
  Timestamp: 10044ms  SCall: 00664  DCall: 00002 [198.22.67.70:4569]
Rx-Frame Retry[ No] -- OSeqno: 007 ISeqno: 006 Type: DTMF    Subclass: 1
  Timestamp: 10643ms  SCall: 00664  DCall: 00002 [198.22.67.70:4569]
Tx-Frame Retry[-01] -- OSeqno: 006 ISeqno: 008 Type: IAX     Subclass: ACK
  Timestamp: 10643ms  SCall: 00002  DCall: 00664 [198.22.67.70:4569]
Rx-Frame Retry[ No] -- OSeqno: 008 ISeqno: 006 Type: DTMF    Subclass: 1
  Timestamp: 11343ms  SCall: 00664  DCall: 00002 [198.22.67.70:4569]
Tx-Frame Retry[-01] -- OSeqno: 006 ISeqno: 009 Type: IAX     Subclass: ACK
  Timestamp: 11343ms  SCall: 00002  DCall: 00664 [198.22.67.70:4569]
Rx-Frame Retry[ No] -- OSeqno: 009 ISeqno: 006 Type: DTMF    Subclass: 1
  Timestamp: 12023ms  SCall: 00664  DCall: 00002 [198.22.67.70:4569]
Tx-Frame Retry[-01] -- OSeqno: 006 ISeqno: 010 Type: IAX     Subclass: ACK

So for whatever reason, the digits don't even show up in debug output while Background() is running, but seem to be recognized and ACKed fine once Background ends. Very very strange.

By: Graham Mainwaring (ghjm) 2006-04-01 23:06:04.000-0600

I'm experiencing this issue as well. Same exact symptoms as lschweiss. This is with * 1.2.5 on CentOS 3.6, using IAX from behind NAT to exgn.net.

Beyond what's already been given, is there any additional information I can provide that would be helpful in resolving this issue?

-Graham

By: salaud (salaud) 2006-04-10 05:22:45

I have the same issue.  Once I turned off jitterbuffer everything worked.

By: Ronald Chan (loloski) 2006-04-15 17:50:42

Guys same issue for 1.2.7.1 :( when jb is enabled it doesn't recognize even a single dtmf, i'll try also to set this on a per user basis and i'll let you know

By: Brian Degenhardt (bmdhacks) 2006-04-15 17:58:38

loloski: can you attach (not post) a log of your failed dtmf sequences with asterisk debug outpt.  IE: run asterisk -vvvvvvcddddddddd (or set debug 10), then run iax debug, then cut/paste the output to a file and upload it.

Also, what is the network topology between these two hosts (how many hops in traceroute, what's the ping time like).  Are you using a commercial ITSP?  Which one?

By: Ronald Chan (loloski) 2006-04-15 18:46:50

bmdhacks: as you requested i attach here trace.txt my failed dtmf when jitterbuffer=yes, i'm using FWD with IAX for testing, my network setup is
linux router + asterisk and a couple of eyebeam softphone.

Please tell me more if you need something from my end.

p.s. when i conducting the test i dial my own FWD number for clarity sake

Thank you!

Best regards,

Ronald

By: Brian Degenhardt (bmdhacks) 2006-04-15 18:57:31

loloski: that trace makes it very diffucult to debug.  Because you're calling yourself, it's very confusing to read.  

Perhaps you can dial out through sip and receive the call via IAX?  Also, *please* turn verbose and debugging on (set debug 10) or -vvvvvdddddd on the command line.  Lastly, if you could provide pingtimes and the number of hops to iax2.fwdnet.net, that would be helpful.

By: Graham Mainwaring (ghjm) 2006-04-15 20:58:42

I am attaching a log of this problem. There are two incoming calls shown here. On the first call, DTMF detection worked correctly (in NVBackgroundDetect). On the second call, DTMF did not work at all. I was pressing touchtones all throughout the NVBackgroundDetect and WaitExten commands, but none were being recognized.

Note that not all of my SIP devices were up and running, so there are some "no route to host" messages - this is unrelated and I have seen the problem occur when these devices are powered on. DTMF is always fully reliable, or not working at all, on a call-by-call basis, but it does not seem to alternate - it is simple chance that the first call worked and the second call did not.

I am also attaching a traceroute to my IAX provider. Please let me know if there is any additional information I can provide.

-Graham

By: Brian Degenhardt (bmdhacks) 2006-04-15 21:03:44

ghjm: you forgot to run iax debug once in asterisk

By: Graham Mainwaring (ghjm) 2006-04-15 21:11:52

Ok, I'm uploading another log file, this time with iax2 debug turned on (oops!). This time, the first call was the one that failed, with no DTMF being recognized despite many being sent; the second call worked.

By: stevekstevek (stevekstevek) 2006-04-15 21:30:39

The only obvious thing I can think of w.r.t. the jitterbuffer making DTMF "not work", is that the jitterbuffer is buffering DTMF frames (and most IAX frames) and not just audio.

The theory behind doing that is that in general, you want control to be synchronized with voice.  Imagine a situation where you are leaving a voicemail, and you have a big (say 1500ms) jitterbuffer;  The VM system lets you press "#" to end the recording.   So you say "I'll pay you A million dollars; just kidding!", and press "#";  If the system acted on the DTMF immediately, then it would possibly cut off a reasonable part of your voice mail.  Similar effects happen when processing HANGUP, and other types of frames.

Now, that said, the cases where this happen are edge cases, and usually, you won't have jitterbuffers that big.   This is the decision that mark took when he did the original IAX2 jitterbuffer, so that's what I followed.

What can happen, though (and seemed to be the case in the original report here), is that the remote end sends DTMF frames with wacko timestamps;  in that case, they could end up being buffered indefinitely.  In the first case, the DTMF frame came in with a timestamp of around 43 days.  So, the Jitterbuffer says, OK, I think these DTMF frames are a bit early;  I'll play them 43 days from now.

If that is happening, it's happening because the remote side is just broken.  We are doing, though, exactly what it's asking.

So, the proper solution would be to fix whatever broken crap is sending stuff like that to us.  Another solution could be to detect this wackiness and deal with it in a reasonable way.  A third (and simplest) solution would be to just not buffer control frames at all.

The third choice shouldn't be too hard to implement -- I think this should do it (I haven't even compiled this, but you get the idea):

Index: chan_iax2.c
===================================================================
--- chan_iax2.c (revision 20388)
+++ chan_iax2.c (working copy)
@@ -2535,7 +2535,9 @@
               type = JB_TYPE_SILENCE;
       }

-       if ( (!ast_test_flag(iaxs[fr->callno], IAX_USEJITTERBUF)) ) {
+       /* bypass the jitterbuffer for this frame if the JB is disabled, or this is not a voice frame */
+       if ( (!ast_test_flag(iaxs[fr->callno], IAX_USEJITTERBUF)) ||
+             (type == JB_TYPE_CONTROL) ) {
               if (tsout)
                       *tsout = fr->ts;
               __do_deliver(fr);

By: Graham Mainwaring (ghjm) 2006-04-15 23:45:18

This works for me.

By: Chip Schweiss (lschweiss) 2006-05-03 17:42:43

I'm about to patch and test the above work around.  Two potential problems come to my attention.

The first is that if the control codes not only will make IVR interaction function weirdly when the jitterbuffer is long, but it could potential end a call too soon when a message is played followed by a hang-up command.  If the message is playing still in the jitterbuffer and a hang-up comes through the message will be cut off.

The second may be an symptom of the same time stamping problem on the sending side.  When working with some VoIP providers that are using jitterbuffers also on IAX2, I periodically get a call connected with one way audio.  

It seems to me that a messed up timestamp could also be causing this problem by over buffering audio the same way.  I seem to see a lot of chatter about excessive jitterbuffer resyncs with very odd time stamps as the cause.  Could this all be related to a timestamp generation problem?  Maybe even a 32bit vs 64bit CPU problem.  

Without digging in and finding the real timestamp problem, it seems a lot of other problems will continue to occur and coming up with odd work arounds for each of them is the wrong way to attack the problem.

If I can find the time this weekend I'll have an additional look at the code to see if I can't find where the timestamp may be getting generated wrong.  From the looks of the odd timestamps it may simply be being used uninitialized somewhere.

By: Serge Vecher (serge-v) 2006-05-04 08:50:11

lschweiss: please report the test results when available. Thanks

By: Andrew Kohlsmith (akohlsmith) 2006-05-11 12:07:20

I see this on svn trunk (as recent as today, r26917) as well with the new IAX2 jitter buffer.

A---[IAX2 dedicated 1-hop link]---B---[SIP or IAX2]---asterlink/nufone
exhibits this problem

A---[IAX2 dedicated 1-hop link]---B---[PRI to telco]
never seems to exhibit the problem.

By: Andrew Kohlsmith (akohlsmith) 2006-05-11 12:15:45

I have that backwards -- DTMF seems to be mostly reliable in the A--IAX2--B--SIP--asterlink/nufone case, and NOT in the A--IAX2--B--PRI case.  I will record this and see what I can see.

By: Andrew Kohlsmith (akohlsmith) 2006-05-11 12:26:49

WOW.  I just uploaded the Monitor()'d audio of a call out the PRI.  the DTMF is badly, badly, badly distorted.

My zaptel gains are not adjusted (i.e. they are at 0.0) .  This is a TE405 with span 1 going to a PRI.  Wow that's bad.

By: Andrew Kohlsmith (akohlsmith) 2006-05-11 12:32:26

Hmm, another call to another IVR (monitored) results in equally disgusting sounding DTMF in the recorded file, but the remote IVR has no issues at all with it.

By: Serge Vecher (serge-v) 2006-05-11 12:43:14

do you have an IAX debug for same??

By: Andrew Kohlsmith (akohlsmith) 2006-05-11 12:56:24

Yeah I have an iax2 debug, but it looks fine:

Rx-Frame Retry[ No] -- OSeqno: 008 ISeqno: 007 Type: DTMF    Subclass: 4
  Timestamp: 12143ms  SCall: 16386  DCall: 00009 [192.168.2.2:4569]
Tx-Frame Retry[-01] -- OSeqno: 007 ISeqno: 009 Type: IAX     Subclass: ACK
  Timestamp: 12143ms  SCall: 00009  DCall: 16386 [192.168.2.2:4569]
Rx-Frame Retry[ No] -- OSeqno: 009 ISeqno: 007 Type: DTMF    Subclass: 4
  Timestamp: 12843ms  SCall: 16386  DCall: 00009 [192.168.2.2:4569]
Tx-Frame Retry[-01] -- OSeqno: 007 ISeqno: 010 Type: IAX     Subclass: ACK
  Timestamp: 12843ms  SCall: 00009  DCall: 16386 [192.168.2.2:4569]
Rx-Frame Retry[ No] -- OSeqno: 010 ISeqno: 007 Type: DTMF    Subclass: 2
  Timestamp: 13563ms  SCall: 16386  DCall: 00009 [192.168.2.2:4569]
Tx-Frame Retry[-01] -- OSeqno: 007 ISeqno: 011 Type: IAX     Subclass: ACK
  Timestamp: 13563ms  SCall: 00009  DCall: 16386 [192.168.2.2:4569]

etc.

By: Serge Vecher (serge-v) 2006-05-24 11:12:28

what revision or 1.2.x version are you observing this one (hopefully the very latest)?

By: Andrew Kohlsmith (akohlsmith) 2006-05-24 11:34:59

I'm running svn trunk, not 1.2.x.  Josh (Canuck) has already said that my particular problem's not related to this bug...

By: Serge Vecher (serge-v) 2006-05-24 11:43:26

lscweiss: the patch to fix the problem is in note: 0044390 and confirmed by ghjm. Did you try it?

By: Chip Schweiss (lschweiss) 2006-05-27 09:24:45

I attepted to test the patch.  However, before applying the patch I tried to reproduce the problem.  Exgn and Teliax were the service providers I discovered the problem with.  The IAX2 debug output I posted was from Teliax.  Currently, with neither of them the problem could be reproduced.  The last time I experienced it was with Exgn and at the time they confirmed they were running Asterisk 1.2.5.  Either they both have moved to newer versions of Asterisk and are no longer sending miss-stamped control codes, or my role of the dice has not been good.  

I've been watching the change logs, but I didn't see any control code/jitterbuffer related patches to IAX2.  Did I miss something that has happened to the time stamping of control codes between 1.2.5 and 1.2.7.1?  For some reason the problem is not currently reproduceable.  

I will set up my own test boxes in the coming week to see if I can produce an unpatched reproduction of the problem before patching.



By: Andrew Kohlsmith (akohlsmith) 2006-05-27 09:55:04

Just an update from my particular case:  It wasn't IAX2 jitter buffer that was causing the trouble with me; it was a bug in the zaptel driver/chan_zap.c that was not clearing out DTMF audio when the VPM was disabled on my TE406.

By: Serge Vecher (serge-v) 2006-06-05 16:07:19

lschweiss: is original problem still there in 1.2.8 or trunk?

By: Serge Vecher (serge-v) 2006-06-19 13:24:53

no response from reporter(s) having the issue as originally described. If anyone can still reproduce this with 1.2.9.1, please ask the bug-marshall to reopen the bug with updated iax debug attached. Thanks.

By: Tilghman Lesher (tilghman) 2006-06-26 14:43:27

Reopen requested by hulber

By: Serge Vecher (serge-v) 2006-06-26 15:09:51

hulber:

1. Please post the console iax debug and iax.conf entries as an attachment to the bug
2. Are you running unmodified sources?
3. Did you try stevek's patch in 0044390

By: Mark Hulber (hulber) 2006-06-26 15:28:09

1. Console output attached and settings are:

  dropcount=2
  maxjitterbuffer=1000
  maxexccessbuffer=80
  minexcessbuffer=10
  jittershrinkrate=1

[jnctn]
  type=user
  auth=rsa
  inkeys=jnctn
  context=junction-in
  qualify=yes
  qualifysmoothing=yes
  jitterbuffer=yes


2. Unmodified Source
3. No, I haven't tried the patch.  I run without the jitterbuffer but tested to see if it was fixed since this was closed.

By: Serge Vecher (serge-v) 2006-06-28 10:57:02

>I run without the jitterbuffer
I thought the whole problem was DTMF distortion when jitterbuffer=yes

By: Mark Hulber (hulber) 2006-06-28 11:13:40

Certainly it is but I don't use the Jitterbuffer now because DTMF doesn't work.  I turned it on again to test if this was fixed in the most current release where I discovered it is not.

By: Serge Vecher (serge-v) 2006-07-12 13:38:45

ok, somebody is confused here. The title of the patch says that DTMF is broken when jitterbuffer is turned on. You are saying that DTMF doesn't work regardless of whethere jitterbuffer is on or off. Please describe exactly what your setup is and how dtmf does not work.

By: damin (damin) 2006-07-26 08:46:03

As a side note, I have two Asterisk boxes running SVN-branch-1.2-r37949. When I have "jitterbuffer=yes" enabled for both of the boxes, DTMF is passed from Server A to Server B, and I can see the IAX2 DTMF events coming in, but the IVR does not respond to the DTMF events.

Setting "jitterbuffer=no" on both sides fixes the problem.

I am using the following configs in iax.conf:

; Server A
[tdm-1]
type=friend
username=tdm-1
host=dynamic
qualify=10000
jitterbuffer=no
forcejitterbuffer=no
trunktimestamps=yes

; Server B
[gw2]
type=friend
username=tdm-1
host=207.166.192.186
qualify=10000
jitterbuffer=no
forcejitterbuffer=no
trunktimestamps=yes

By: jeffery palmer (darren1713) 2006-08-14 14:25:39

I have just experienced exactly this issue on an asterisk box when receiving incoming calls connected with Junction Networks. When I add (forcejitterbuffer=yes) to the user declaration, I loose DTMF. When forcejitterbuffer is removed, DTMF passes with no issues.

Asterisk SVN-branch-1.2-r39379M built by root @ mail1 on a i686 running Linux on 2006-08-11 20:27:36 UTC

By: Serge Vecher (serge-v) 2006-09-06 11:00:33

darren1713: what modifications have you done to the Asterisk sources? Can you please test with 1.2.11 (non-modified sources please)?

By: Serge Vecher (serge-v) 2006-09-27 13:51:40

once again, this report is abandoned... If you think you are able to reproduce something that is related to this bug with the latest release (1.2.12.1 currently), please do not reopen this issue and open a new one. Thank you.