Unity DTMF Added Digits

mmelton.porterco · ‎01-19-2016

Ok, we are having an issue where some calls come into unity from some cell phone providers we are getting a DTMF added event for every dialed digit. We have a TAC case opened with not much of a resolution, other than we are better off now than before at least not all incoming calls are getting duplicated digits. This all started after we swapped from a frontier re-seller t1 sip to a Ethernet sip with a smaller provider who uses a Metasys Switch

01:10:03, New Call, CalledId=8825, RedirectingId=53550, AltRedirectingId=, Origin=16, Reason=4, CallGuid=7F24A5A8742F403E956DE9C859FA6C54, CallerName=MATT MELTON, LastRedirectingId=, AltLastRedirectingId=, LastRedirectingReason=4, PortDisplayName=PhoneSystem-1-012,[Origin=Unknown],[Reason=Forward No Answer]
01:10:03, Changed the current search by extension search space from <No scope> to 'uconn01 Search Space' ({c08fa531-0e15-4ba1-828a-90f6e880f914})
01:10:03, Changed the current search by name search space from <No scope> to 'uconn01 Search Space' ({c08fa531-0e15-4ba1-828a-90f6e880f914})
01:10:03, AttemptForward
01:10:03, State - AttemptForward.cde!Dummy
01:10:03, Event is [NULL]
01:10:03, PHTransfer
01:10:03, State - PHTransfer.cde!LoadInfo
01:10:03, Event is [TrueEvent]
01:10:03, PHGreeting
01:10:03, State - PHGreeting.cde!PlayGreeting
01:10:03, Call answered if needed
01:10:03, Playing greeting for Subscriber: Animal Shelter
01:10:07, DTMF received [1]
01:10:09, DTMF added [1]
01:10:11, Event is [NULL]
01:10:11, PHGreeting
01:10:11, State - PHGreeting.cde!PlayGreeting
01:10:11, Call answered if needed
01:10:11, Playing greeting for Subscriber: Animal Shelter
01:10:24, DTMF received [1]
01:10:26, DTMF added [1]
01:10:29, Event is [NULL]
01:10:29, PHGreeting
01:10:29, State - PHGreeting.cde!PlayGreeting
01:10:29, Call answered if needed
01:10:29, Playing greeting for Subscriber: Animal Shelter
01:10:37, Event is [HangupEvent]
01:10:37, State - PHGreeting.cde!DoHangup
01:10:37, Event is [HangupEvent]

When I do a show sip-ua calls, I get the following showing that it is Negotiated Dtmf-relay : inband-voice

Call 3
SIP Call ID : 0gQAAC8WAAACBAAALxYAAFiC+x+r05b1XTXBFhwz+U2tLqdg0KjYLcuEnZvGVBuZ@216.176.135.133
State of the call : STATE_ACTIVE (7)
Substate of the call : SUBSTATE_NONE (0)
Calling Number : 2193134412
Called Number : 2194653550
Called URI : sip:2194653550@66.***.***.***:5060;transport=udp
Bit Flags : 0x8C4401C 0x10000100 0x4
CC Call ID : 203447
Source IP Address (Sig ): 66.***.***.***
Destn SIP Req Addr:Port : [216.***.***.***]:5060
Destn SIP Resp Addr:Port: [216.***.***.***]:5060
Destination Name : 216.***.***.***
Number of Media Streams : 1
Number of Active Streams: 1
RTP Fork Object : 0x0
Media Mode : flow-through
Media Stream 1
State of the stream : STREAM_ACTIVE
Stream Call ID : 203447
Stream Type : voice-only (0)
Stream Media Addr Type : 1
Negotiated Codec : g711ulaw (160 bytes)
Codec Payload Type : 0
Negotiated Dtmf-relay : inband-voice
Dtmf-relay Payload Type : 0
QoS ID : -1
Local QoS Strength : BestEffort
Negotiated QoS Strength : BestEffort
Negotiated QoS Direction : None
Local QoS Status : None
Media Source IP Addr:Port: [66.***.***.***]:30588
Media Dest IP Addr:Port : [216.***.***.***]:55596

SIP UAC CALL INFO
Call 1
SIP Call ID : 27FEF1A3-BE1B11E5-BBE0A0F2-5C083B82@192.168.100.6
State of the call : STATE_ACTIVE (7)
Substate of the call : SUBSTATE_NONE (0)
Calling Number : 73134412
Called Number : 2194653550
Called URI : sip:2194653550@172.11.20.1:5060
Bit Flags : 0xC04018 0x90000100 0x80
CC Call ID : 203448
Source IP Address (Sig ): 192.168.100.6
Destn SIP Req Addr:Port : [172.11.20.1]:5060
Destn SIP Resp Addr:Port: [172.11.20.1]:5060
Destination Name : 172.11.20.1
Number of Media Streams : 1
Number of Active Streams: 1
RTP Fork Object : 0x0
Media Mode : flow-through
Media Stream 1
State of the stream : STREAM_ACTIVE
Stream Call ID : 203448
Stream Type : voice-only (0)
Stream Media Addr Type : 1
Negotiated Codec : g711ulaw (160 bytes)
Codec Payload Type : 0
Negotiated Dtmf-relay : inband-voice
Dtmf-relay Payload Type : 0
QoS ID : -1
Local QoS Strength : BestEffort
Negotiated QoS Strength : BestEffort
Negotiated QoS Direction : None
Local QoS Status : None
Media Source IP Addr:Port: [192.168.100.6]:30682
Media Dest IP Addr:Port : [172.11.17.1]:26570

My dial peers look like this

dial-peer voice 300 voip
description *** To/From CUCM subscriber for Voice ***
translation-profile outgoing filter_219
call-block translation-profile incoming call_block
preference 1
destination-pattern 219.......
session protocol sipv2
session target ipv4:172.11.20.1
incoming called-number 7T
voice-class codec 1
voice-class sip asymmetric payload full
voice-class sip asserted-id pai
voice-class sip privacy-policy passthru
voice-class sip early-offer forced
voice-class sip bind control source-interface Loopback0
voice-class sip bind media source-interface Loopback0
dtmf-relay rtp-nte digit-drop sip-kpml
fax rate 14400 bytes 48
fax protocol pass-through g711ulaw
no vad
!
dial-peer voice 301 voip
description *** To/From CUCM publisher for Voice ***
translation-profile outgoing VP
preference 2
destination-pattern 219.......
session protocol sipv2
session target ipv4:172.11.17.1
incoming called-number 7T
voice-class codec 1
voice-class sip asymmetric payload full
voice-class sip asserted-id pai
voice-class sip privacy-policy passthru
voice-class sip early-offer forced
voice-class sip bind control source-interface Loopback0
voice-class sip bind media source-interface Loopback0
dtmf-relay rtp-nte digit-drop sip-kpml
fax rate 14400 bytes 48
fax protocol pass-through g711ulaw
no vad
!

From RTMT

NOTIFY sip:172.11.17.3:5060;transport=tcp SIP/2.0
Via: SIP/2.0/TCP 172.11.20.1:5060;branch=z9hG4bK128e93a4add9e
From: " MATT MELTON" < sip:73134412@172.11.20.1> ;tag=133052~4816ed5f-b0ba-4f04-877b-db1f0a7a9f9f-39828232
To: < sip:8825@172.11.17.3> ;tag=28496022862b4912950d850e7dec3b8d
Call-ID: 3b2ef980-69e18a08-3aa1-1140bac@172.11.20.1
CSeq: 108 NOTIFY
Max-Forwards: 70
Date: Tue, 19 Jan 2016 19:10:34 GMT
User-Agent: Cisco-CUCM10.5
Event: kpml
Subscription-State: terminated;reason=timeout
Contact: < sip:172.11.20.1:5060;transport=tcp>
P-Asserted-Identity: " MATT MELTON" < sip:73134412@172.11.20.1>
Content-Type: application/kpml-response+xml
Content-Length: 348
< ?xml version=" 1.0" encoding=" UTF-8" ?>
< kpml-response xmlns=" urn:ietf:params:xml:ns:kpml-response" xmlns:xsi=" http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation=" urn:ietf:params:xml:ns:kpml-response kpml-response.xsd" code=" 487" digits=" " forced_flush=" false" suppressed=" false" tag=" dtmf" text=" Subscription Expired" version=" 1.0" />

Detailed Sip Message

NOTIFY sip:172.11.20.1:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.100.6:5060;branch=z9hG4bK3BC024FE
From: " MATT MELTON" < sip:73134412@192.168.100.6> ;tag=4DDA3F14-871
To: < sip:2194653550@172.11.20.1> ;tag=133051~4816ed5f-b0ba-4f04-877b-db1f0a7a9f9f-39828229
Call-ID: 127225DD-BE1711E5-B87EA0F2-5C083B82@192.168.100.6
CSeq: 105 NOTIFY
Max-Forwards: 70
Date: Tue, 19 Jan 2016 19:10:34 GMT
User-Agent: Cisco-SIPGateway/IOS-15.6.1.T0a
Event: kpml
Subscription-State: terminated
Contact: < sip:73134412@192.168.100.6:5060>
P-Asserted-Identity: " MATT MELTON" < sip:73134412@192.168.100.6>
Content-Type: application/kpml-response+xml
Content-Length: 109
< ?xml version=" 1.0" encoding=" UTF-8" ?> < kpml-response version=" 1.0" code=" 487" text=" Subscription Expired" />

Jonathan Schulenberg · ‎01-19-2016

Can you also collect this output from the router for a test call:

debug ccsip messages
show call active voice brief

Inband voice is very unusual. Does the provider not support RFC2833 (aka rtp-nte)?

Also, just to manage expectations: I have seen this problem in a specific geography before and it was effectively impossible I fix. I used to work in Wisconsin and this would crop up even with PRIs before SIP. Since it was happening across multiple LECs, the theory was that a tandem switch or some common element that the calls were traversing in the state was causing it.whatever it was, every phone company was confident it wasn't them! Funny how that works.

mmelton.porterco · ‎01-21-2016

On this particular call I pressed 1, got a dtmf added [1] and then pressed 2 and it transferred me

Jonathan Schulenberg · ‎01-21-2016

I don't have an answer at this point but wanted to point out what I have noticed in the logs you provided. (btw- Attaching them as a text file would keep the thread much shorter and thus more likely to get more eyeballs.)

The call sets up correctly but 27 seconds in the call the carrier sends a RE-INVITE at 18:42:51.783 which CUBE seems not to like. While the carrier keeps RFC2833 support in the SDP, CUBE strips this off when it forwards the RE-INVITE to CUCM at 18:42:51.791. It then appears that the call is put on hold at the 18:42:51.795 mark since CUCM changes the SDP to inactive and then engages a unicast music on hold resource at 18:42:53.915 before the call ends at 18:42:55.823.

So, my next question is whether you pressed the DTMF digit before the 27 second mark while the call had negotiated RFC2833? If yes, then the I would redo this with an additional debug of debug voip rtp session named-event. That will allow you to see whether the carrier sent you duplicate RFC2833 packets or not. If they are then the ball is squarely in their court to address.

PS- If you open a TAC case over this they will probably also want debug voip ccapi inout.

balukr · ‎11-20-2017

Did you had a chance to fix this issue? I have same problem with one of our customer and trying to see where this issue on Unity.

Ayodeji Okanlawon · ‎01-21-2016

My first suggestion is to remove rtp-nte digit drop from your dial peer. What thus does is to extract the inband dtmf from your provider and and send it out of band.. You don't want this especially since your provider supports rfc 2833..

So try and remove it and see if it makes a difference

Please rate all useful posts