[Home]

Summary:ASTERISK-08285: Reading DTMF fails on IAX2
Reporter:gdhgdh (gdhgdh)Labels:
Date Opened:2006-12-05 16:58:39.000-0600Date Closed:2007-06-30 09:20:07
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Applications/app_voicemail
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) asterisk1.4.0beta4-dtmf-sip-rtp-debug.txt
( 1) hardphone.cap
( 2) iaxcomm.cap
( 3) iaxcomm-svn.cap
Description:Upgrading from 1.2.13 to 1.4.0-beta3, and VoiceMailMain refuses to acknowledge DTMF digits. Tested with IAXComm, kiax and Sparkle (SIP). No capability to test a Zaptel interface.

   -- Accepting AUTHENTICATED call from 10.0.2.166:
   -- Executing [2500@from-ip:1] VoiceMailMain("IAX2/1401-2", "") in new stack

Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 004 Type: DTMF_E  Subclass: 1
  Timestamp: 01587ms  SCall: 03221  DCall: 00002 [10.0.2.166:4569]
Tx-Frame Retry[-01] -- OSeqno: 004 ISeqno: 004 Type: IAX     Subclass: ACK
  Timestamp: 01587ms  SCall: 00002  DCall: 03221 [10.0.2.166:4569]
Rx-Frame Retry[ No] -- OSeqno: 004 ISeqno: 004 Type: IAX     Subclass: PING
  Timestamp: 02004ms  SCall: 03221  DCall: 00002 [10.0.2.166:4569]
Tx-Frame Retry[000] -- OSeqno: 004 ISeqno: 005 Type: IAX     Subclass: PONG
  Timestamp: 02004ms  SCall: 00002  DCall: 03221 [10.0.2.166:4569]
  RR_JITTER       : 0
  RR_LOSS         : 0
  RR_PKTS         : 2
  RR_DELAY        : 40
  RR_DROPPED      : 0
  RR_OUTOFORDER   : 0

Rx-Frame Retry[ No] -- OSeqno: 005 ISeqno: 005 Type: IAX     Subclass: ACK
  Timestamp: 02004ms  SCall: 03221  DCall: 00002 [10.0.2.166:4569]
Rx-Frame Retry[ No] -- OSeqno: 005 ISeqno: 005 Type: DTMF_E  Subclass: 0
  Timestamp: 03235ms  SCall: 03221  DCall: 00002 [10.0.2.166:4569]
Tx-Frame Retry[-01] -- OSeqno: 005 ISeqno: 006 Type: IAX     Subclass: ACK
  Timestamp: 03235ms  SCall: 00002  DCall: 03221 [10.0.2.166:4569]
Rx-Frame Retry[ No] -- OSeqno: 006 ISeqno: 005 Type: DTMF_E  Subclass: 0
  Timestamp: 03723ms  SCall: 03221  DCall: 00002 [10.0.2.166:4569]
Tx-Frame Retry[-01] -- OSeqno: 005 ISeqno: 007 Type: IAX     Subclass: ACK
  Timestamp: 03723ms  SCall: 00002  DCall: 03221 [10.0.2.166:4569]
Rx-Frame Retry[ No] -- OSeqno: 007 ISeqno: 005 Type: DTMF_E  Subclass: 0
  Timestamp: 04243ms  SCall: 03221  DCall: 00002 [10.0.2.166:4569]
Tx-Frame Retry[-01] -- OSeqno: 005 ISeqno: 008 Type: IAX     Subclass: ACK
  Timestamp: 04243ms  SCall: 00002  DCall: 03221 [10.0.2.166:4569]
Rx-Frame Retry[ No] -- OSeqno: 008 ISeqno: 005 Type: DTMF_E  Subclass: #
  Timestamp: 04988ms  SCall: 03221  DCall: 00002 [10.0.2.166:4569]
Tx-Frame Retry[-01] -- OSeqno: 005 ISeqno: 009 Type: IAX     Subclass: ACK
  Timestamp: 04988ms  SCall: 00002  DCall: 03221 [10.0.2.166:4569]
   -- Playing 'vm-password' (language 'en')

IAX debug shows Asterisk is rx'd and ACK'ing each DTMF press, but seems to do nothing with it - verbose + debug on 9 give no extra info.


Comments:By: gdhgdh (gdhgdh) 2006-12-05 16:59:43.000-0600

Just for completeness, /usr/lib/asterisk/modules was deleted before 'make install' for 1.4.0-beta3
By: Jason Parker (jparker) 2006-12-05 17:34:02.000-0600

I see that voicemail is asking for the password after the DTMF frames...  Is there a long timeout before that is played or something?
By: gdhgdh (gdhgdh) 2006-12-06 03:00:56.000-0600

OK, this seems to be affecting IAX only. Fault on SIP was a false positive caused by a broken client.

My paste was incomplete; as soon as the channel is answered, there's

   -- Playing 'vm-login' (language 'en')

So, no delay at all - it's just not picking up any digits. If I let the IAX client sit and don't attempt to type any digits, Asterisk will cycle automatically to

   -- Playing 'vm-password' (language 'en')

as I'd expect.

Again for completeness, I tried using the same IAX client with our live server on * 1.2.4, and it works flawlessly. All machines are on the same LAN in the same subnet - no firewalls / other filtering.
By: Joshua C. Colp (jcolp) 2006-12-06 09:30:02.000-0600

I tried using idefisk to a 1.4 checkout from SVN and it worked fine. Can you add dtmf in logger.conf to the console line? It will spit out the DTMF digit if it goes through the Asterisk core fine and will allow us to locate where the issue may be.
By: gdhgdh (gdhgdh) 2006-12-06 09:37:24.000-0600

-- Registered IAX2 '1401' (AUTHENTICATED) at 10.0.0.100:4569
[2006-12-06 15:33:51] NOTICE[9393]: chan_iax2.c:5631 update_registry: Restricting registration for peer '1401' to 60 seconds (requested 300)
   -- Accepting AUTHENTICATED call from 10.0.0.100:
      > requested format = gsm,
      > requested prefs = (),
      > actual format = gsm,
      > host prefs = (g729|gsm),
      > priority = mine
   -- Executing [2500@from-ip:1] VoiceMailMain("IAX2/1401-3", "") in new stack
   -- Playing 'vm-login' (language 'en')
[2006-12-06 15:36:13] DTMF[13400]: channel.c:2080 __ast_read: DTMF end '1' received on IAX2/1401-3
[2006-12-06 15:36:14] DTMF[13400]: channel.c:2080 __ast_read: DTMF end '2' received on IAX2/1401-3
[2006-12-06 15:36:14] DTMF[13400]: channel.c:2080 __ast_read: DTMF end '3' received on IAX2/1401-3
[2006-12-06 15:36:15] DTMF[13400]: channel.c:2080 __ast_read: DTMF end '4' received on IAX2/1401-3
[2006-12-06 15:36:16] DTMF[13400]: channel.c:2080 __ast_read: DTMF end '#' received on IAX2/1401-3

(long pause)

   -- Playing 'vm-password' (language 'en')
[2006-12-06 15:36:24] DTMF[13400]: channel.c:2080 __ast_read: DTMF end '5' received on IAX2/1401-3
[2006-12-06 15:36:25] DTMF[13400]: channel.c:2080 __ast_read: DTMF end '6' received on IAX2/1401-3
[2006-12-06 15:36:25] DTMF[13400]: channel.c:2080 __ast_read: DTMF end '7' received on IAX2/1401-3
[2006-12-06 15:36:26] DTMF[13400]: channel.c:2080 __ast_read: DTMF end '8' received on IAX2/1401-3
[2006-12-06 15:36:26] DTMF[13400]: channel.c:2080 __ast_read: DTMF end '#' received on IAX2/1401-3

(long pause)

   -- Incorrect password '' for user '1401' (context = default)
   -- Playing 'vm-incorrect-mailbox' (language 'en')

i.e. still no joy :(


By: Scott Keagy (skeagy) 2006-12-11 09:07:26.000-0600

Here's my topology (refer to it for what DTMF works and what doesn't). All boxes running Asterisk 1.4beta3 and using SIP with RFC 2833 explicitly enabled in peers:

SIP provider (Tekelec switch?)
    |sip
    |
Asterisk_BoxA (ztdummy)
|          |
|          |sip
|          |
|           --- Asterisk_BoxB (ztdummy)
|
|
|sip
|
Asterisk_BoxC (wctdm)
|           |
|           |sip
|           |
|            --- Cisco7960
|
|
|analog
|loopstart
|
POTS lines

1) Calls from SIP provider to BoxC (via BoxA): DTMF tones work with MeetMe and Voicemail, and they show up in log when DTMF is included in logger.conf
2) Calls to BoxC via POTS, DTMF works fine
3) Calls from SIP phones registered to BoxC, DTMF works fine for accessing MeetMe and VoicemailMain on BoxC
4) Calls from SIP phones registered to BoxC, destined for BoxB (via BoxA, canreinvite=no): DTMF 100% not recognized!! No log messages re: digits, and applications act like they never heard the digits (from perspective of BoxA, BoxB, *and* BoxC). I would expect at least BoxC to see the DTMF in this situation.

Asterisk can interpret the DTMF from Cisco7960 when the phone is directly registered to the box where VoicemailMain and MeetMe is running. But when the phone is calling through the box to which it is registered and destined for an app on a different box, then suddenly there is no more visibility to DTMF presses. Maybe something about relaying a call stops a deeper inspection, and RFC 2833 tones are not even logged when dtmf is enabled on the relay box.

But that doesn't explain why the destination box fails to see any DTMF digits!


By: Joshua C. Colp (jcolp) 2006-12-18 20:50:14.000-0600

Are Box A and Box B both running Asterisk 1.4? If not then you may have issues because you didn't add the rfcc2833compensate option to the appropriate entry which causes the newer RFC2833 in the RTP stack to compensate for the broken RFC2833 from 1.2 and earlier versions. Without this DTMF would not act reliably for number 4.
By: gdhgdh (gdhgdh) 2006-12-19 03:16:11.000-0600

file: You said "Without this DTMF would not act reliably for number 4. "

This is surely a red herring because both skeagy and myself are experiencing a situation in where *NO* DTMF digits are being processed via IAX, even those in my case I can see the:

[2006-12-06 15:36:13] DTMF[13400]: channel.c:2080 __ast_read: DTMF end '1' received on IAX2/1401-3

debug messages, but they aren't passing any further into the core.

This happens even with 1.4.0 beta4
By: gdhgdh (gdhgdh) 2006-12-19 03:40:36.000-0600

This is insane. All hardphone clients work fine with DTMF, whilst all softphone clients are failing. IAXComm, Sparkle, Ekiga all fail (IAX and SIP), whilst an IAX-firmware PA1688 chip phone works, as it does with SIP firmware, and as do Linksys SPA921 sets :/

I've uploaded tcpdump captures in case anyone can see a difference - both are of dialling 2500 for voicemail, entering 1234 as user and 5678 as password...
By: djflux (djflux) 2006-12-19 08:36:37.000-0600

I am having the same issue with Ekiga 2.0.2 as shipped with Fedora Core 6 and asterisk-1.4.0-beta4.  I've uploaded a SIP and RTP debug for a default 1.4.0-beta4 installation just calling 1000 to access the demo and pressing 500 to try to test IAX.

Let me know if you need any other information.
By: Joshua C. Colp (jcolp) 2006-12-19 09:14:56.000-0600

gdhgdh: With the way you wrote your listing of scenarios it sounded as though you were using SIP to connect Asterisk machines and DTMF was failing with RFC2833, as it would because a configuration option was not turned on.

djflux: The Ekiga RFC2833 packets are awfully broken. In order to make our RFC2833 more compatible with the rest of the world we had to be a little less forgiving with received DTMF. The compensation option won't even help to fix the Ekiga DTMF since it never says when the digit actually ends... not good.
By: gdhgdh (gdhgdh) 2006-12-19 09:28:14.000-0600

file: Nope, this is one Asterisk server, just connecting clients - intentionally very straightforward :)

The SIP is a distraction - IAX is where I need to get things going... and I don't see any special options in configs/iax.conf.sample  hence the reason for a bug report rather than just asking on-list  :(
By: djflux (djflux) 2006-12-20 09:28:02.000-0600

file: Thanks for the pointer.  It seems opal 2.2.2 (and 2.2.3 on Fedora Rawhide) sends broken DTMF packets.  I checked with the Ekiga and opal developers and this issue is resolved in the opal CVS.  Check:

http://bugzilla.gnome.org/show_bug.cgi?id=327988

for more details.

I've also opened a bug with Red Hat on the broken opal that includes patches to fix the opal SIP DTMF problems in their builds:

https://bugzilla.redhat.com/bugzilla/show_bug.cgi?id=220333

Putting notes here in case someone comes along with the same problem with SIP.

gdhgdh: if your softphones use the opal libraries, that may be your problem as well.
By: Joshua C. Colp (jcolp) 2007-01-25 13:03:27.000-0600

I'm back and was wondering if you could try the latest revision.
By: gdhgdh (gdhgdh) 2007-01-26 03:57:01.000-0600

Yes, still failing with SVN from this morning. However, the output from 'debug channel all' is interesting:

This is me entering mailbox 1234# then password 5678#

   -- Executing [2500@from-ip:1] VoiceMailMain("IAX2/1401-1", "") in new stack
   -- <IAX2/1401-1> Playing 'vm-login' (language 'en')
<< [ TYPE: DTMF Begin (12) SUBCLASS: 1 (49) ] [IAX2/1401-1]
<< [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [IAX2/1401-1]
<< [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [IAX2/1401-1]
<< [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [IAX2/1401-1]
<< [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [IAX2/1401-1]

<long pause whilst login times out>

   -- <IAX2/1401-1> Playing 'vm-password' (language 'en')
<< [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [IAX2/1401-1]
<< [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [IAX2/1401-1]
<< [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [IAX2/1401-1]
<< [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [IAX2/1401-1]
<< [ TYPE: Null Frame (5) SUBCLASS: N/A (0) ] [IAX2/1401-1]
   -- Incorrect password '' for user '1401' (context = default)
   -- <IAX2/1401-1> Playing 'vm-incorrect-mailbox' (language 'en')
   -- Hungup 'IAX2/1401-1'
By: gdhgdh (gdhgdh) 2007-01-26 04:00:17.000-0600

Uploaded a tcpdump capture of the client capture during this time (it probably features SSH packets, too) as iaxcomm-svn.cap
By: Serge Vecher (serge-v) 2007-01-31 16:13:55.000-0600

gdhgdh: please specify a revision (i.e. 51234), rather than the time when svn branch has been checked out.
By: gdhgdh (gdhgdh) 2007-01-31 16:20:13.000-0600

I've no idea. The build scripts went a bit wibbly when shoehorning in the SVN rev number... 'asterisk -V' gives me...
Asterisk SVN--r

Can I deduce the current version number from the .svn directory  or some 'subversion' commandline majik?
By: djflux (djflux) 2007-01-31 16:31:41.000-0600

gdhgdh: from a layman/non-developer point of view, it appears to me that your client is doing the same thing that ekiga was doing - sending a DTMF begin but no end.
By: Serge Vecher (serge-v) 2007-02-05 10:30:21.000-0600

gdhgdh: check the ./.svn/entries file.
By: gdhgdh (gdhgdh) 2007-02-05 12:39:14.000-0600

The first promising candidate is on the 4th line of the file: 51363
By: Serge Vecher (serge-v) 2007-02-07 10:20:18.000-0600

there have been some revisions to dtmf handling since then, please delete the repository, do a fresh checkout, make clean and test (latest revision is > 53100 now).
By: gdhgdh (gdhgdh) 2007-02-07 10:45:29.000-0600

Sorry, the standard of response of 'try the latest SVN' has had no effect. Same behaviour with 53359. I even tried the latest 1.37 of the Idefisk client to no change (!)
By: Serge Vecher (serge-v) 2007-02-07 14:57:47.000-0600

thanks for checking and reporting back; we need the debug then, of the kind produced by djflux. Make sure debug is set for console => in logger.conf.
By: gdhgdh (gdhgdh) 2007-02-08 03:09:19.000-0600

Is this any use? You can clearly see Asterisk receiving 'DTMF end' for each digit of mailbox 2345 and password 6789, yet nothing is actually 'done' with the values.

   -- Accepting AUTHENTICATED call from 10.0.0.204:
      > requested format = gsm,
      > requested prefs = (),
      > actual format = alaw,
      > host prefs = (alaw|ulaw),
      > priority = mine
[2007-02-08 09:06:27] DEBUG[17681]: pbx.c:1693 pbx_extension_helper: Launching 'VoiceMailMain'
   -- Executing [2500@from-ip:1] VoiceMailMain("IAX2/1401-1", "") in new stack
[2007-02-08 09:06:27] DEBUG[17681]: app_voicemail.c:6234 vm_execmain: Before ast_answer
[2007-02-08 09:06:27] DEBUG[17681]: chan_iax2.c:3282 iax2_answer: Answering IAX2 call
[2007-02-08 09:06:27] DEBUG[17681]: devicestate.c:382 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel IAX2/1401-1
[2007-02-08 09:06:27] DEBUG[17681]: devicestate.c:244 ast_device_state: No provider found, checking channel drivers for IAX2 - 1401
[2007-02-08 09:06:27] DEBUG[17681]: chan_iax2.c:9765 iax2_devicestate: Checking device state for device 1401
[2007-02-08 09:06:27] DEBUG[17681]: chan_iax2.c:9773 iax2_devicestate: iax2_devicestate: Found peer. What's device state of 1401? addr=-872415222, defaddr=0 maxms=0, lastms=0
[2007-02-08 09:06:27] DEBUG[17681]: channel.c:919 channel_find_locked: Avoiding initial deadlock for channel '0x8216e78'
[2007-02-08 09:06:27] DEBUG[17681]: devicestate.c:366 do_state_change: Changing state for IAX2/1401 - state 2 (In use)
[2007-02-08 09:06:27] DEBUG[17681]: app_queue.c:568 changethread: Device 'IAX2/1401' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[2007-02-08 09:06:28] DEBUG[17681]: channel.c:2755 set_format: Set channel IAX2/1401-1 to write format gsm
   -- <IAX2/1401-1> Playing 'vm-login' (language 'en')
[2007-02-08 09:06:30] DEBUG[17681]: channel.c:2755 set_format: Set channel IAX2/1401-1 to write format alaw
[2007-02-08 09:06:31] DTMF[17681]: channel.c:2135 __ast_read: DTMF end '2' received on IAX2/1401-1
[2007-02-08 09:06:32] DTMF[17681]: channel.c:2135 __ast_read: DTMF end '3' received on IAX2/1401-1
[2007-02-08 09:06:33] DTMF[17681]: channel.c:2135 __ast_read: DTMF end '4' received on IAX2/1401-1
[2007-02-08 09:06:34] DTMF[17681]: channel.c:2135 __ast_read: DTMF end '5' received on IAX2/1401-1
[2007-02-08 09:06:35] DTMF[17681]: channel.c:2135 __ast_read: DTMF end '#' received on IAX2/1401-1
muf*CLI>
muf*CLI>
[2007-02-08 09:06:40] DEBUG[17681]: app_voicemail.c:6141 vm_authenticate: Before find user for mailbox 1401
[2007-02-08 09:06:40] DEBUG[17681]: channel.c:2755 set_format: Set channel IAX2/1401-1 to write format gsm
   -- <IAX2/1401-1> Playing 'vm-password' (language 'en')
[2007-02-08 09:06:41] DEBUG[17681]: channel.c:2755 set_format: Set channel IAX2/1401-1 to write format alaw
[2007-02-08 09:06:42] DEBUG[17681]: devicestate.c:382 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel IAX2/1401
[2007-02-08 09:06:42] DEBUG[17681]: devicestate.c:244 ast_device_state: No provider found, checking channel drivers for IAX2 - 1401
[2007-02-08 09:06:42] DEBUG[17681]: chan_iax2.c:9765 iax2_devicestate: Checking device state for device 1401
[2007-02-08 09:06:42] DEBUG[17681]: chan_iax2.c:9773 iax2_devicestate: iax2_devicestate: Found peer. What's device state of 1401? addr=-872415222, defaddr=0 maxms=0, lastms=0
[2007-02-08 09:06:42] DEBUG[17681]: devicestate.c:366 do_state_change: Changing state for IAX2/1401 - state 2 (In use)
[2007-02-08 09:06:42] DEBUG[17681]: app_queue.c:568 changethread: Device 'IAX2/1401' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[2007-02-08 09:06:45] DTMF[17681]: channel.c:2135 __ast_read: DTMF end '6' received on IAX2/1401-1
[2007-02-08 09:06:45] DTMF[17681]: channel.c:2135 __ast_read: DTMF end '7' received on IAX2/1401-1
[2007-02-08 09:06:46] DTMF[17681]: channel.c:2135 __ast_read: DTMF end '8' received on IAX2/1401-1
[2007-02-08 09:06:46] DTMF[17681]: channel.c:2135 __ast_read: DTMF end '9' received on IAX2/1401-1
[2007-02-08 09:06:47] DTMF[17681]: channel.c:2135 __ast_read: DTMF end '#' received on IAX2/1401-1
muf*CLI>
muf*CLI>
   -- Incorrect password '' for user '1401' (context = default)
[2007-02-08 09:06:51] DEBUG[17681]: channel.c:2755 set_format: Set channel IAX2/1401-1 to write format gsm
   -- <IAX2/1401-1> Playing 'vm-incorrect-mailbox' (language 'en')
[2007-02-08 09:06:54] DEBUG[17681]: channel.c:2755 set_format: Set channel IAX2/1401-1 to write format alaw
By: Matt Riddell (zx81) 2007-02-28 23:22:55.000-0600

We've hit the same problem with an IAXClient based softphone with Asterisk version 1.4 (SVN-branch-1.4-r54103).

It was showing on one machine and not the other, and setting internaltiming=yes in asterisk.conf under options resolved this for us.

One thing to note is that Asterisk is only receiving DTMF END frames and sometimes their lengths are a bit strange:

[Mar  1 18:11:44] DTMF[12728]: channel.c:2224 __ast_read: DTMF end '1' received on IAX2/matt-7, duration 12049728 ms
[Mar  1 18:11:46] DTMF[12728]: channel.c:2224 __ast_read: DTMF end '2' received on IAX2/matt-7, duration 0 ms

Codec doesn't make a difference.

Machine is running with no zap hardware, latest zaptel (ztdummy) modules.

Can anyone else confirm if this fixes it for you?

The application we were running which showed us the problem was a simple Background(MySoundFile)


By: gdhgdh (gdhgdh) 2007-03-01 02:52:43.000-0600

I'm afraid not; launching asterisk with the -I option makes no difference here.
By: Matt Riddell (zx81) 2007-03-01 17:02:52.000-0600

What about if you do something like:

exten => s,1,Answer()
exten => s,2,Read(myvar)
exten => s,3,NoOp(${myvar})

Does it print out anything in the NoOp line?
By: Matt Riddell (zx81) 2007-03-04 17:58:56.000-0600

We're still seing this too.  Internal timing helped but didn't fix it.
By: Matt Riddell (zx81) 2007-03-04 22:56:15.000-0600

We're still seeing it:


   -- Executing [s@avmx714:2] BackGround("IAX2/matt-8", "avmx714_ivr") in new stack
   -- <IAX2/matt-8> Playing 'avmx714_ivr' (language 'en')
[Mar  5 17:54:21] DTMF[23805]: channel.c:2224 __ast_read: DTMF end '1' received on IAX2/matt-8, duration -1212916452 ms
[Mar  5 17:54:24] DTMF[23805]: channel.c:2224 __ast_read: DTMF end '1' received on IAX2/matt-8, duration -1212916452 ms
[Mar  5 17:54:25] DTMF[23805]: channel.c:2224 __ast_read: DTMF end '1' received on IAX2/matt-8, duration 12049728 ms
[Mar  5 17:54:26] DTMF[23805]: channel.c:2224 __ast_read: DTMF end '1' received on IAX2/matt-8, duration 12049728 ms
[Mar  5 17:54:27] DTMF[23805]: channel.c:2224 __ast_read: DTMF end '2' received on IAX2/matt-8, duration 12049728 ms
[Mar  5 17:54:28] DTMF[23805]: channel.c:2224 __ast_read: DTMF end '1' received on IAX2/matt-8, duration 12049728 ms

The DTMF is received but seems to be ignored.  Those lengths look pretty out there.
By: Matt Riddell (zx81) 2007-03-04 23:33:22.000-0600

(Disclaimer on file - continue reading)

Um yeah, so it's in the creating based on dtmf length.

This isn't a fix, but sorts the problem on my customer's machine.

Basically the length of the dtmf is all wrong but seems to be specified.  So by ignoring the VLDTMF stuff for now (the customer doesn't need it), we got the machines going again with this:

Index: main/channel.c
===================================================================
--- main/channel.c      (revision 57258)
+++ main/channel.c      (working copy)
@@ -2237,9 +2237,9 @@
                               ast_set_flag(chan, AST_FLAG_EMULATE_DTMF);
                               chan->emulate_dtmf_digit = f->subclass;
                               chan->dtmf_begin_tv = ast_tvnow();
-                               if (f->len)
-                                       chan->emulate_dtmf_duration = f->len;
-                               else
+//                             if (f->len)
+//                                     chan->emulate_dtmf_duration = f->len;
+//                             else
                                       chan->emulate_dtmf_duration = AST_DEFAULT_EMULATE_DTMF_DURATION;
                       } else {
                               ast_clear_flag(chan, AST_FLAG_IN_DTMF);
By: Matt Riddell (zx81) 2007-03-04 23:43:25.000-0600

Either someone needs to make some sanity checks for the length or find out what's causing them to get so big/small.

Volunteers?
By: Joshua C. Colp (jcolp) 2007-03-05 13:21:31.000-0600

Can everyone please try 1.4 as of revision 57914?
By: Colin Beckingham (colbec) 2007-03-05 16:32:29.000-0600

I believe I am seeing this also with 1.4.1 on SuSe 10.1 using idefisk v. 1.37 (IAX2) over a dialup connection through a TDM11B.
Unfortunately I don't think I can add anything to the report as yet. It happens sporadically and I don't yet see a pattern.
It always fails on reading the password (mailbox number is always read correctly), and when it fails it does not see any of the digits sent.
I can get ComedianMail to respond correctly after a failure sometimes by restarting asterisk, sometimes by hanging up the idefisk call (not restarting idefisk) and redialling.
By: Matt Riddell (zx81) 2007-03-07 14:14:49.000-0600

Hi,

I moved the channel.c file to my home directory, did a make distclean followed by ./configure && make && make install.

I then restarted Asterisk (now SVN-branch-1.4-r58243) and retested using IDEFisk.

It works flawlessly.

Edit (the DTMF comes through as 0ms now - which is good):

[Mar  8 09:19:02] DTMF[27222]: channel.c:2224 __ast_read: DTMF end '1' received on IAX2/matt-7, duration 0 ms

[Mar  8 09:19:04] DTMF[27222]: channel.c:2224 __ast_read: DTMF end '1' received on IAX2/matt-7, duration 0 ms


By: Colin Beckingham (colbec) 2007-03-07 15:23:41.000-0600

ZX81: try again in 24 hours, my experience is that an * restart will fix the issue, then it comes back after a while. Just happened to me again.
By: Serge Vecher (serge-v) 2007-03-07 15:27:16.000-0600

make sure you a testing with a clean installation from 1.4.1 tarball.
By: Matt Riddell (zx81) 2007-03-08 14:32:53.000-0600

Correct.

The error is back:

   -- Executing [s@avmx714:2] BackGround("IAX2/matt-13", "avmx714_ivr") in new stack
   -- <IAX2/matt-13> Playing 'avmx714_ivr' (language 'en')
[Mar  9 09:32:18] DTMF[12451]: channel.c:2224 __ast_read: DTMF end '1' received on IAX2/matt-13, duration 12049728 ms
   -- Registered IAX2 'student' (AUTHENTICATED) at 202.40.171.39:32916
[Mar  9 09:32:22] DTMF[12451]: channel.c:2224 __ast_read: DTMF end '1' received on IAX2/matt-13, duration 12049728 ms
 == Spawn extension (avmx714, s, 2) exited non-zero on 'IAX2/matt-13'
By: Colin Beckingham (colbec) 2007-03-08 15:59:30.000-0600

Serge-v: thank you for the reminder. I am indeed testing from the most recent svn. Updated earlier today, recompiled, worked fine initially, now 4 hours later the error is back. This seems to indicate a variable initialization issue, perhaps?
By: Russell Bryant (russell) 2007-03-10 12:17:39.000-0600

I just made a few more fixes in 58705 of 1.4 that may help this issue.

For those having the problem, what are some of the system details?  distro?  uname -a?
By: Colin Beckingham (colbec) 2007-03-10 13:11:23.000-0600

Linux suse 2.6.16.21-0.25-smp #1 SMP Tue Sep 19 07:26:15 UTC 2006 i686 i686 i386 GNU/Linux

Initial load of new version is ok. Immediately noted a slight delay in response to '#' to hang up. In my test I normally do mailbox, password, response comes back no messages, then while voice prompt continues with options I hit '#' before that option is voiced. Normally the hangup is almost immediate, in this version there is a delay of about 4 secs, but comedian mail does comply. I will post again shortly.
By: Matt Riddell (zx81) 2007-03-10 18:13:56.000-0600

I won't be able to test again for a couple of days, but here is the uname -a from the machine we're seeing this on:

Linux ocean 2.6.18-1.2257.fc5smp #1 SMP Fri Dec 15 16:33:51 EST 2006 i686 i686 i386 GNU/Linux
By: Colin Beckingham (colbec) 2007-03-12 10:50:27

Many hours later and still working fine here. My previous observation on delay after '#' must have been a one-off, I am not able to repeat it now.
By: Serge Vecher (serge-v) 2007-03-12 11:32:58

colbec, thanks for testing and reporting --> will await for zx81's test results before closing.
By: Matt Riddell (zx81) 2007-03-13 04:06:16

Appears to be working here fine too.
By: Serge Vecher (serge-v) 2007-03-13 08:36:49

fixed in 1.4 rev. 58705 and trunk rev 58706. Thanks for quick reports back!