DTMF Digits Falsely Detected

Home » Asterisk Users » DTMF Digits Falsely Detected
Asterisk Users 17 Comments

Hi,

I have a context that basically does:

Wait(1)
Background(message)
WaitExten(10)

_6XXXXXX,1,DoSomething

The problem is that when I reach this context and press some digits (eg. 6566604) then I can see in the log that Asterisk reads 6655666. So it’s actually reading the digits twice. How can I avoid this?
Incoming channel type is ISDN (mISDN).

Thanks,

Vieri

17 thoughts on - DTMF Digits Falsely Detected

  • Are you saying every digit twice, or some digits twice. Where is the call originating from, GSM cell phone or landline?

    Which version of asterisk are you using?

    Alec Davis

  • Hi,

    Started seeing similar abnormality today after the 1.8.16.0 upgrade.

    In my case digits were repeated 3 times.

    Several observations:

    * The problem only manifested itself on SIP channel. OOH323 and DAHDI
    did not exhibit this problem.
    * I was able to dial the extension with no issues, the problem started
    in the Voice Mail application.

    For example, in the case below I entered “430#”

    [2012-09-14 11:50:06] VERBOSE[32019] app_read.c: — User entered
    ‘444333000’

    Following is the excerpt from the DTMF log:

    [2012-09-14 11:50:05] DTMF[32019] channel.c: DTMF begin ‘4’ received on SIP/462-00000000
    [2012-09-14 11:50:05] DTMF[32019] channel.c: DTMF begin ignored ‘4’ on SIP/462-00000000
    [2012-09-14 11:50:05] DTMF[32019] channel.c: DTMF end ‘4’ received on SIP/462-00000000, duration 300 ms
    [2012-09-14 11:50:05] DTMF[32019] channel.c: DTMF end passthrough ‘4’ on SIP/462-00000000
    [2012-09-14 11:50:05] DTMF[32019] channel.c: DTMF end ‘4’ received on SIP/462-00000000, duration 300 ms
    [2012-09-14 11:50:05] DTMF[32019] channel.c: DTMF end passthrough ‘4’ on SIP/462-00000000
    [2012-09-14 11:50:05] DTMF[32019] channel.c: DTMF end ‘4’ received on SIP/462-00000000, duration 300 ms
    [2012-09-14 11:50:05] DTMF[32019] channel.c: DTMF end passthrough ‘4’ on SIP/462-00000000
    [2012-09-14 11:50:05] DTMF[32019] channel.c: DTMF begin ‘3’ received on SIP/462-00000000
    [2012-09-14 11:50:05] DTMF[32019] channel.c: DTMF begin ignored ‘3’ on SIP/462-00000000
    [2012-09-14 11:50:06] DTMF[32019] channel.c: DTMF end ‘3’ received on SIP/462-00000000, duration 300 ms
    [2012-09-14 11:50:06] DTMF[32019] channel.c: DTMF end passthrough ‘3’ on SIP/462-00000000
    [2012-09-14 11:50:06] DTMF[32019] channel.c: DTMF end ‘3’ received on SIP/462-00000000, duration 300 ms
    [2012-09-14 11:50:06] DTMF[32019] channel.c: DTMF end passthrough ‘3’ on SIP/462-00000000
    [2012-09-14 11:50:06] DTMF[32019] channel.c: DTMF end ‘3’ received on SIP/462-00000000, duration 300 ms
    [2012-09-14 11:50:06] DTMF[32019] channel.c: DTMF end passthrough ‘3’ on SIP/462-00000000
    [2012-09-14 11:50:06] DTMF[32019] channel.c: DTMF begin ‘0’ received on SIP/462-00000000
    [2012-09-14 11:50:06] DTMF[32019] channel.c: DTMF begin ignored ‘0’ on SIP/462-00000000
    [2012-09-14 11:50:06] DTMF[32019] channel.c: DTMF end ‘0’ received on SIP/462-00000000, duration 300 ms
    [2012-09-14 11:50:06] DTMF[32019] channel.c: DTMF end passthrough ‘0’ on SIP/462-00000000
    [2012-09-14 11:50:06] DTMF[32019] channel.c: DTMF end ‘0’ received on SIP/462-00000000, duration 300 ms
    [2012-09-14 11:50:06] DTMF[32019] channel.c: DTMF end passthrough ‘0’ on SIP/462-00000000
    [2012-09-14 11:50:06] DTMF[32019] channel.c: DTMF end ‘0’ received on SIP/462-00000000, duration 300 ms
    [2012-09-14 11:50:06] DTMF[32019] channel.c: DTMF end passthrough ‘0’ on SIP/462-00000000
    [2012-09-14 11:50:06] DTMF[32019] channel.c: DTMF begin ‘#’ received on SIP/462-00000000
    [2012-09-14 11:50:06] DTMF[32019] channel.c: DTMF begin ignored ‘#’ on SIP/462-00000000
    [2012-09-14 11:50:06] DTMF[32019] channel.c: DTMF end ‘#’ received on SIP/462-00000000, duration 300 ms
    [2012-09-14 11:50:06] DTMF[32019] channel.c: DTMF end passthrough ‘#’ on SIP/462-00000000
    [2012-09-14 11:50:06] DTMF[32019] channel.c: DTMF end ‘#’ received on SIP/462-00000000, duration 300 ms
    [2012-09-14 11:50:06] DTMF[32019] channel.c: DTMF end ‘#’ received on SIP/462-00000000, duration 300 ms
    [2012-09-14 11:50:06] DTMF[32019] channel.c: DTMF begin emulation of ‘#’
    with duration 300 queued on SIP/462-00000000
    [2012-09-14 11:50:06] DTMF[32019] channel.c: DTMF end ‘#’ received on SIP/462-00000000, duration 300 ms
    [2012-09-14 11:50:07] DTMF[32019] channel.c: DTMF end emulation of ‘#’
    queued on SIP/462-00000000
    [2012-09-14 11:50:07] DTMF[32019] channel.c: DTMF end ‘#’ received on SIP/462-00000000, duration 300 ms
    [2012-09-14 11:50:07] DTMF[32019] channel.c: DTMF begin emulation of ‘#’
    with duration 300 queued on SIP/462-00000000

    As a comparison here is an excerpt from the DTMF log of a similar call from the same extension before the upgrade (Asterisk 1.8.15.1):

    [2012-09-13 14:41:25] DTMF[7934] channel.c: DTMF begin ‘4’ received on SIP/462-0000007b
    [2012-09-13 14:41:25] DTMF[7934] channel.c: DTMF begin ignored ‘4’ on SIP/462-0000007b
    [2012-09-13 14:41:25] DTMF[7934] channel.c: DTMF end ‘4’ received on SIP/462-0000007b, duration 300 ms
    [2012-09-13 14:41:25] DTMF[7934] channel.c: DTMF end passthrough ‘4’ on SIP/462-0000007b
    [2012-09-13 14:41:25] DTMF[7934] channel.c: DTMF begin ‘3’ received on SIP/462-0000007b
    [2012-09-13 14:41:25] DTMF[7934] channel.c: DTMF begin ignored ‘3’ on SIP/462-0000007b
    [2012-09-13 14:41:25] DTMF[7934] channel.c: DTMF end ‘3’ received on SIP/462-0000007b, duration 300 ms
    [2012-09-13 14:41:25] DTMF[7934] channel.c: DTMF end passthrough ‘3’ on SIP/462-0000007b
    [2012-09-13 14:41:25] DTMF[7934] channel.c: DTMF begin ‘0’ received on SIP/462-0000007b
    [2012-09-13 14:41:25] DTMF[7934] channel.c: DTMF begin ignored ‘0’ on SIP/462-0000007b
    [2012-09-13 14:41:26] DTMF[7934] channel.c: DTMF end ‘0’ received on SIP/462-0000007b, duration 300 ms
    [2012-09-13 14:41:26] DTMF[7934] channel.c: DTMF end passthrough ‘0’ on SIP/462-0000007b
    [2012-09-13 14:41:27] DTMF[7934] channel.c: DTMF begin ‘#’ received on SIP/462-0000007b
    [2012-09-13 14:41:27] DTMF[7934] channel.c: DTMF begin ignored ‘#’ on SIP/462-0000007b
    [2012-09-13 14:41:27] DTMF[7934] channel.c: DTMF end ‘#’ received on SIP/462-0000007b, duration 300 ms

    No changes in the environment, no changes to the Soft Phone settings

    I did resolve the issue by switching Soft Phones, and the difference is in DTMF duration as I can see.

    [2012-09-14 13:43:02] DTMF[32606] channel.c: DTMF begin ‘4’ received on SIP/462-0000000e
    [2012-09-14 13:43:02] DTMF[32606] channel.c: DTMF begin ignored ‘4’ on SIP/462-0000000e
    [2012-09-14 13:43:02] DTMF[32606] channel.c: DTMF end ‘4’ received on SIP/462-0000000e, duration 120 ms
    [2012-09-14 13:43:02] DTMF[32606] channel.c: DTMF end passthrough ‘4’ on SIP/462-0000000e
    [2012-09-14 13:43:02] DTMF[32606] channel.c: DTMF begin ‘3’ received on SIP/462-0000000e
    [2012-09-14 13:43:02] DTMF[32606] channel.c: DTMF begin ignored ‘3’ on SIP/462-0000000e
    [2012-09-14 13:43:02] DTMF[32606] channel.c: DTMF end ‘3’ received on SIP/462-0000000e, duration 100 ms
    [2012-09-14 13:43:02] DTMF[32606] channel.c: DTMF end passthrough ‘3’ on SIP/462-0000000e
    [2012-09-14 13:43:02] DTMF[32606] channel.c: DTMF begin ‘0’ received on SIP/462-0000000e
    [2012-09-14 13:43:02] DTMF[32606] channel.c: DTMF begin ignored ‘0’ on SIP/462-0000000e
    [2012-09-14 13:43:02] DTMF[32606] channel.c: DTMF end ‘0’ received on SIP/462-0000000e, duration 160 ms
    [2012-09-14 13:43:02] DTMF[32606] channel.c: DTMF end passthrough ‘0’ on SIP/462-0000000e
    [2012-09-14 13:43:03] DTMF[32606] channel.c: DTMF begin ‘#’ received on SIP/462-0000000e
    [2012-09-14 13:43:03] DTMF[32606] channel.c: DTMF begin ignored ‘#’ on SIP/462-0000000e
    [2012-09-14 13:43:03] DTMF[32606] channel.c: DTMF end ‘#’ received on SIP/462-0000000e, duration 80 ms

    I believe Asterisk 1.8.16.0 introduced an issue where a longer DTMF
    causes a multiple digit recognition effect.

    -Vladimir

  • Hopefully the initial poster still has the configuration to produce the files for you.

    Are you saying the DTMF logs I attached do not provide enough evidence to support the theory of the DTMF length being the cause of this issue?

    -Vladimir

  • Vladimir, What was the Softphone/Version you were using to get this to fail.

    I’m using an old version of X-Lite, V3.0 build 56125 and with asterisk 1.8.16.0 when in voicemail I was unable to get any errors. DTMF log below.

    [2012-09-15 22:36:39.974909] DTMF[1706] channel.c: DTMF begin ‘1’ received on SIP/alec-00000009
    [2012-09-15 22:36:39.974985] DTMF[1706] channel.c: DTMF begin ignored ‘1’ on SIP/alec-00000009
    [2012-09-15 22:36:40.514978] DTMF[1706] channel.c: DTMF end ‘1’ received on SIP/alec-00000009, duration 560 ms
    [2012-09-15 22:36:40.515037] DTMF[1706] channel.c: DTMF end passthrough ‘1’
    on SIP/alec-00000009
    [2012-09-15 22:36:41.014955] DTMF[1706] channel.c: DTMF begin ‘2’ received on SIP/alec-00000009
    [2012-09-15 22:36:41.015009] DTMF[1706] channel.c: DTMF begin ignored ‘2’ on SIP/alec-00000009
    [2012-09-15 22:36:41.459045] DTMF[1706] channel.c: DTMF end ‘2’ received on SIP/alec-00000009, duration 460 ms
    [2012-09-15 22:36:41.459089] DTMF[1706] channel.c: DTMF end passthrough ‘2’
    on SIP/alec-00000009
    [2012-09-15 22:36:41.909042] DTMF[1706] channel.c: DTMF begin ‘3’ received on SIP/alec-00000009
    [2012-09-15 22:36:41.909093] DTMF[1706] channel.c: DTMF begin ignored ‘3’ on SIP/alec-00000009
    [2012-09-15 22:36:42.429177] DTMF[1706] channel.c: DTMF end ‘3’ received on SIP/alec-00000009, duration 540 ms
    [2012-09-15 22:36:42.429236] DTMF[1706] channel.c: DTMF end passthrough ‘3’
    on SIP/alec-00000009
    [2012-09-15 22:36:42.849091] DTMF[1706] channel.c: DTMF begin ‘4’ received on SIP/alec-00000009
    [2012-09-15 22:36:42.849185] DTMF[1706] channel.c: DTMF begin ignored ‘4’ on SIP/alec-00000009
    [2012-09-15 22:36:44.489226] DTMF[1706] channel.c: DTMF end ‘4’ received on SIP/alec-00000009, duration 1660

  • Alec,

    Thank you for looking into that.

    X-Lite v3.0, build 41150, is what I switched to.

    Interestingly in your log DTMF durations are even greater than in my original sampling. Well, maybe my “duration” theory is not right. But needed to exclude it first as it was on the surface. I am assuming you dialed the digits normally, i.e. did not try to push a button longer than usual.

    The Soft Phone I used originally was Minipax v2.8.5. Please contact me off-list if you need the Windows installation package as the maker’s site is down as of this moment.

    Another interesting thing which our friend Matt apparently did not pay attention to was the fact that dialing worked fine with Minipax, it was the applications where problems started. Sounds like his latest patch was not applied consistently throughout the system. Good news for now, but could change in the future.

    Thank you, Vladimir

  • Matt,

    Please see my answers in-line. Thank you for looking into the issue.

    -Vladimir

    Can you please quote the appropriate RFC here? It looks like the UA
    just uses the real time of an event for time stamping. I still would like to understand the logic and the math here as 121920+24004320, not 122080 or 122240.

    Why does the retransmission happen at all? Maybe something else is broken?

    Is that something mandated by the respective RFC? In other words is it
    “MUST” or “MAY” per RFC? Or is it not there at all?

    See the question above.

    Sorry, my mistake. Somehow I assumed that dialing was processed in IVR. Even in this case my statement would have been incorrect as IVR is yet another application.

    I need to test with IVR, but my bet results will be the same as with Voice Mail. At least that is how it sounds from your explanation of what behavior was modified and where.

    As I did not know what exactly caused the DTMF recognition failure I
    tested almost all channels I use, e.g. I called in via a POTS line.

    Once again please refer to the RFC you use as the specification.

  • Yes I did press digits longer than usual, as you’d highlighted that duration may be an issue. Pressing digits normally and fast, gave the expected correct results.

    Alec

  • Alec,

    Thank you for the clarification.

    And just to make sure. In both scenarios, normal digit press and prolonged digit press, you did not reproduce the problem we are discussing with X-Lite. Is that correct?

    Thank you, Vladimir

  • Correct, everything with X-Lite 3.0 and asterisk 1.8.16.0 worked correctly with short, normal and long key presses while in voicemail.

    Alec

  • Matt,

    I appreciate you taking time to explain the application logic in detail along with interpreting the RFC logic. That BTW finally gave me a push to read RFC 2833.

    It sounds like the soft phone I used did not implement the RFC
    requirements precisely as the requirement to keep the same time stamp on the three (3) redundant packets is “SHOULD.”

    On the other hand the RFC leaves the room open for the far end reassembly algorithms.

    As you have mentioned one of the objectives of the Asterisk development is to not break the old behavior, a.k.a. “backwards compatibility.” If no more elegant solution to satisfy both DTMF transmission scenarios will be found a per-client setting can be introduced to the effect of following the “new” or “old’ algorithm. I will be happy to help you with testing.

    Thank you, Vladimir