Cisco Support Community
cancel
Showing results for 
Search instead for 
Did you mean: 

Understanding DTMF negotiation and troubleshooting on SIP Trunks

DTMF play an important role in telephony solution as we all know. This document attempts to look at the detail traces from CUCM and gateway logs so as to understand DTMF interaction and how to troubleshoot them.

Two key elements to this:

1. DTMF supported by the Phone or IVR or unity connection

2. DTMF negotiated between CUCM and the associated gateway (sip trunk, h323 gateway or mgcp gateway)

DTMF mismatch often arise from different DTMF method supported by the two endpoints in a call. By endpoints here I mean a Phone/IVR/voicemail application and the gateway/trunk

We will be looking at different DTMF scenarios and look at both cucm and gateway logs

In all these test CUCM sip trunk dtmf method is set to No preference

SCENARIO 1:

  • Cisco Jabber for windows, SIP-KPML configured on gateway dial-peer

jabber4windows----SIP----CUCM--SIP---Gateway---E1--PSTN

  • Gateway dial-peer config

dial-peer voice 3 voip

incoming called number .

no vad

dtmf-relay sip-kpml

Let’s look at the relevant section of the logs

  • CUCM Logs:

This is the outbound CUCM INVITE sent to the Gateway

10:59:28.180 |//SIP/SIPUdp/wait_SdlSPISignal: Outgoing SIP UDP message to 172.10.104.32:[5060]:

[311079,NET]

INVITE sip:908446930701@172.10.104.32:5060 SIP/2.0

Via: SIP/2.0/UDP 172.10.40.11:5060;branch=z9hG4bK25e275fb33fa2

From: "Deji okanlawon" <sip:01215246408@172.10.40.11>;tag=155101~ffa80926-5fac-4dd6-b405-2dbbc56ae9a2-544608971

To: <sip:908446930701@172.10.104.32>

Date: Fri, 24 May 2013 09:59:28 GMT

Call-ID: 9de24580-19f13a00-25c63-b28690a@172.10.40.11

Supported: timer,resource-priority,replaces

Min-SE: 1800

User-Agent: Cisco-CUCM8.6

Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY

CSeq: 101 INVITE

Expires: 180

Allow-Events: presence, kpml

Supported: X-cisco-srtp-fallback

Supported: Geolocation

Call-Info: <sip:172.10.40.11:5060>;method="NOTIFY;Event=telephone-event;Duration=500"

Cisco-Guid: 2648851840-0000065536-0000000282-0187197706

Session-Expires: 84600

P-Asserted-Identity: "Deji okanlawon" <sip:01215246408@172.10.40.11>

Remote-Party-ID: "Deji okanlawon" <sip:01215246408@172.10.40.11>;party=calling;screen=yes;privacy=off

Contact: <sip:01215246408@172.10.40.11:5060>;video;bfcp

Max-Forwards: 69

Content-Length: 0

This is the 183 Session progress we get back from the gateway. Note the DTMF advertised in the SDP

NO RTP-NTE

SIP/2.0 183 Session Progress

Via: SIP/2.0/UDP 172.10.40.11:5060;branch=z9hG4bK25e275fb33fa2

From: "Deji okanlawon" <sip:01215246408@172.10.40.11>;tag=155101~ffa80926-5fac-4dd6-b405-2dbbc56ae9a2-544608971

To: <sip:908446930701@172.10.104.32>;tag=4F448086-750

Date: Fri, 24 May 2013 09:59:28 GMT

Call-ID: 9de24580-19f13a00-25c63-b28690a@172.10.40.11

CSeq: 101 INVITE

Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER

Allow-Events: kpml, telephone-event

Remote-Party-ID: <sip:08446930701@172.10.104.32>;party=called;screen=no;privacy=off

Contact: <sip:908446930701@172.10.104.32:5060>

Supported: sdp-anat

Server: Cisco-SIPGateway/IOS-12.x

Content-Type: application/sdp

Content-Disposition: session;handling=required

Content-Length: 217

v=0

o=CiscoSystemsSIP-GW-UserAgent 9228 1435 IN IP4 172.10.104.32

s=SIP Call

c=IN IP4 172.10.104.32

t=0 0

m=audio 16384 RTP/AVP 18

c=IN IP4 172.10.104.32

a=rtpmap:18 G729/8000

a=fmtp:18 annexb=no

a=ptime:20

Next we see CUCM telling us the DTMF capabilites of the two endpoints (sip trunk and gateway

NB: The "mLocalDtmfCaps" (highlighted) refers to the dtmf methods supported by CUCM...Here we see that CUCM supports unsolicited, KPML and RTP-NTE

On the right hand side after the mEndppointsDtmfCaps (highlighted blue) refers to the dtmf supported by the gateway: which we can see is only KPML. We can see in the trace CUCM detects no inband support

10:59:28.427 |//SIP/SIPCdpc(22,74,282)/ci=544608971/ccbId=155101/scbId=0/updateAllowedMethods: mEndpointAllowedMethods=07ff|22,100,230,1.155730^172.10.104.32^*

10:59:28.427 |setEndpointsDtmfCaps: KPML Supported.|*^*^*

10:59:28.427 |setEndpointsDtmfCaps: Detected NO inband DTMF support.|*^*^*

10:59:28.427 |SIP DTMF Info: mLocalDtmfCaps...UNSOL=1, KPML=1, Inband=1(101) mEndppointsDtmfCaps...UNSOL=0, KPML=1, Inband=0(0) mDefaultTelephonyEvent=101, mDtmfPreference=1, mMtpAllocated=0|*^*^*

Looking at the advertised capabilites, both sides support KPML, KPML is chosing as the dtmf transport method

NB: The ACK sent out to the gateway by CUCM doesn’t advertise RFC2833

10:59:30.684 |//SIP/SIPUdp/wait_SdlSPISignal: Outgoing SIP UDP message to 172.10.104.32:[5060]:

[311084,NET]

ACK sip:908446930701@172.10.104.32:5060 SIP/2.0

Via: SIP/2.0/UDP 172.10.40.11:5060;branch=z9hG4bK25e2860b3d2ab

From: "Deji okanlawon" <sip:01215246408@172.10.40.11>;tag=155101~ffa80926-5fac-4dd6-b405-2dbbc56ae9a2-544608971

To: <sip:908446930701@172.10.104.32>;tag=4F448086-750

Date: Fri, 24 May 2013 09:59:28 GMT

Call-ID: 9de24580-19f13a00-25c63-b28690a@172.10.40.11

Max-Forwards: 70

CSeq: 101 ACK

Allow-Events: presence, kpml

Content-Type: application/sdp

Content-Length: 182

v=0

o=CiscoSystemsCCM-SIP 155101 1 IN IP4 172.10.40.11

s=SIP Call

c=IN IP4 172.10.40.190

t=0 0

m=audio 23012 RTP/AVP 18

a=rtpmap:18 G729/8000

a=ptime:20

a=fmtp:18 annexb=no

The next thing we see is that the gateway sends a subscribe for KPML event

10:59:30.695 |//SIP/SIPUdp/wait_UdpDataInd: Incoming SIP UDP message size 906 from 172.10.104.32:[52877]:

[311085,NET]

SUBSCRIBE sip:01215246408@172.10.40.11:5060 SIP/2.0

Via: SIP/2.0/UDP 172.10.104.32:5060;branch=z9hG4bKC1AF6

From: <sip:908446930701@172.10.104.32>;tag=4F448086-750

To: "Deji okanlawon" <sip:01215246408@172.10.40.11>;tag=155101~ffa80926-5fac-4dd6-b405-2dbbc56ae9a2-544608971

Call-ID: 9de24580-19f13a00-25c63-b28690a@172.10.40.11

CSeq: 101 SUBSCRIBE

Max-Forwards: 70

Date: Fri, 24 May 2013 09:59:30 GMT

User-Agent: Cisco-SIPGateway/IOS-12.x

Event: kpml

Expires: 7200

Contact: <sip:172.10.104.32:5060>

Content-Type: application/kpml-request+xml

Content-Length: 327

<?xml version="1.0" encoding="UTF-8"?><kpml-request xmlns="urn:ietf:params:xml:ns:kpml-request" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="urn:ietf:params:xml:ns:kpml-request kpml-request.xsd" version="1.0"><pattern persist="persist"><regex tag="dtmf">[x*#ABCD]</regex></pattern></kpml-request>

Next CUCM sends a 200 OK to the SUBSCRIBE

10:59:30.695 |//SIP/SIPUdp/wait_SdlSPISignal: Outgoing SIP UDP message to 172.10.104.32:[5060]:

[311086,NET]

SIP/2.0 200 OK

Via: SIP/2.0/UDP 172.10.104.32:5060;branch=z9hG4bKC1AF6

From: <sip:908446930701@172.10.104.32>;tag=4F448086-750

To: "Deji okanlawon" <sip:01215246408@172.10.40.11>;tag=155101~ffa80926-5fac-4dd6-b405-2dbbc56ae9a2-544608971

Date: Fri, 24 May 2013 09:59:30 GMT

Call-ID: 9de24580-19f13a00-25c63-b28690a@172.10.40.11

CSeq: 101 SUBSCRIBE

Contact: <sip:01215246408@172.10.40.11:5060>

Expires: 7200

Content-Length: 0

Once the endpoint successfully subscribe to KPML,CUCM sends a NOTIFY for KPML event,this is how DTMF will be sent out

NOTIFY sip:172.10.104.32:5060 SIP/2.0

Via: SIP/2.0/UDP 172.10.40.11:5060;branch=z9hG4bK25e29422465a0

From: "Deji okanlawon" <sip:01215246408@172.10.40.11>;tag=155101~ffa80926-5fac-4dd6-b405-2dbbc56ae9a2-544608971

To: <sip:908446930701@172.10.104.32>;tag=4F448086-750

Call-ID: 9de24580-19f13a00-25c63-b28690a@172.10.40.11

CSeq: 102 NOTIFY

Max-Forwards: 70

Date: Fri, 24 May 2013 09:59:30 GMT

User-Agent: Cisco-CUCM8.6

Event: kpml

Subscription-State: active;expires=7200

Contact: <sip:01215246408@172.10.40.11:5060>

P-Asserted-Identity: "Deji okanlawon" <sip:01215246408@172.10.40.11>

Content-Length: 0

We get 200 OK from gateway

10:59:30.705 |//SIP/SIPUdp/wait_UdpDataInd: Incoming SIP UDP message size 380 from 172.10.104.32:[5060]:

[311088,NET]

SIP/2.0 200 OK

Via: SIP/2.0/UDP 172.10.40.11:5060;branch=z9hG4bK25e29422465a0

From: "Deji okanlawon" <sip:01215246408@172.10.40.11>;tag=155101~ffa80926-5fac-4dd6-b405-2dbbc56ae9a2-544608971

To: <sip:908446930701@172.10.104.32>;tag=4F448086-750

Date: Fri, 24 May 2013 09:59:30 GMT

Call-ID: 9de24580-19f13a00-25c63-b28690a@172.10.40.11

CSeq: 102 NOTIFY

Content-Length: 0

Now we see the actual DTMF digits been SENT Look out for the "star_CcUserInfoReq" line..

for each digit pressed this line is generated and you see the actual digit

10:59:35.969 |//SIP/SIPCdpc(22,74,282)/ci=544608971/ccbId=155101/scbId=0/star_CcUserInfoReq: Outbound DTMF method selected is 3. Digit=0 and isMTPPassingThru2833=0|23,100,63,1.1151^172.10.40.190^*

Next we see CUCM sends the digit received out via KPML

NB: we do not see the “KeypadButton” message in this trace because the IP phone is not registered to the CUCM in the sip trunk CUCM group. This trace exists on that CUCM.

10:59:35.969 |//SIP/SIPCdpc(22,74,282)/ci=544608971/ccbId=155101/scbId=155102/sendDtmfViaKpml: ccUserInfoReq.digit=0|23,100,63,1.1151^172.10.40.190^*

10:59:35.969 |//SIP/SIPCdpc(22,74,282)/ci=544608971/ccbId=155101/scbId=155102/sendDtmfViaKpml: notifyContent->mDigits=0|23,100,63,1.1151^172.10.40.190^*

Next we see CUCM sending the digit to the gateway via a NOTIFY

To see the actual digit look into the xml encoding of the NOTIFY message, you can see digit=0

10:59:35.969 |//SIP/SIPUdp/wait_SdlSPISignal: Outgoing SIP UDP message to 172.10.104.32:[5060]:

[311089,NET]

NOTIFY sip:172.10.104.32:5060 SIP/2.0

Via: SIP/2.0/UDP 172.10.40.11:5060;branch=z9hG4bK25e2a78a7f435

From: "Deji okanlawon" <sip:01215246408@172.10.40.11>;tag=155101~ffa80926-5fac-4dd6-b405-2dbbc56ae9a2-544608971

To: <sip:908446930701@172.10.104.32>;tag=4F448086-750

Call-ID: 9de24580-19f13a00-25c63-b28690a@172.10.40.11

CSeq: 103 NOTIFY

Max-Forwards: 70

Date: Fri, 24 May 2013 09:59:35 GMT

User-Agent: Cisco-CUCM8.6

Event: kpml

Subscription-State: active;expires=7195

Contact: <sip:01215246408@172.10.40.11:5060>

P-Asserted-Identity: "Deji okanlawon" <sip:01215246408@172.10.40.11>

Content-Type: application/kpml-response+xml

Content-Length: 336

<?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="200" digits="0" forced_flush="false" suppressed="false" tag="dtmf" text="Success" version="1.0"/>

Finally we get a 200 OK to the NOTIFY from the gateway

10:59:35.979 |//SIP/SIPUdp/wait_UdpDataInd: Incoming SIP UDP message size 380 from 172.10.104.32:[5060]:

[311090,NET]

SIP/2.0 200 OK

Via: SIP/2.0/UDP 172.10.40.11:5060;branch=z9hG4bK25e2a78a7f435

From: "Deji okanlawon" <sip:01215246408@172.10.40.11>;tag=155101~ffa80926-5fac-4dd6-b405-2dbbc56ae9a2-544608971

To: <sip:908446930701@172.10.104.32>;tag=4F448086-750

Date: Fri, 24 May 2013 09:59:35 GMT

Call-ID: 9de24580-19f13a00-25c63-b28690a@172.10.40.11

CSeq: 103 NOTIFY

Content-Length: 0

On The gateway we see this...

080984: May 24 10:59:35.905 BST: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:

Received:

NOTIFY sip:172.10.104.32:5060 SIP/2.0

Via: SIP/2.0/UDP 172.10.40.11:5060;branch=z9hG4bK25e2a78a7f435

From: "Deji okanlawon" <sip:01215246408@172.10.40.11>;tag=155101~ffa80926-5fac-4dd6-b405-2dbbc56ae9a2-544608971

To: <sip:908446930701@172.10.104.32>;tag=4F448086-750

Call-ID: 9de24580-19f13a00-25c63-b28690a@172.10.40.11

CSeq: 103 NOTIFY

Max-Forwards: 70

Date: Fri, 24 May 2013 09:59:35 GMT

User-Agent: Cisco-CUCM8.6

Event: kpml

Subscription-State: active;expires=7195

Contact: <sip:01215246408@172.10.40.11:5060>

P-Asserted-Identity: "Deji okanlawon" <sip:01215246408@172.10.40.11>

Content-Type: application/kpml-response+xml

Content-Length: 336

<?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="200" digits="0" forced_flush="false" suppressed="false" tag="dtmf" text="Success" version="1.0"/>

080985: May 24 10:59:35.905 BST: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:

Sent:

SIP/2.0 200 OK

Via: SIP/2.0/UDP 172.10.40.11:5060;branch=z9hG4bK25e2a78a7f435

From: "Deji okanlawon" <sip:01215246408@172.10.40.11>;tag=155101~ffa80926-5fac-4dd6-b405-2dbbc56ae9a2-544608971

To: <sip:908446930701@172.10.104.32>;tag=4F448086-750

Date: Fri, 24 May 2013 09:59:35 GMT

Call-ID: 9de24580-19f13a00-25c63-b28690a@172.10.40.11

CSeq: 103 NOTIFY

Content-Length: 0

  • Hence can see and conclude that the gateway receives the digits sent by CUCM

SCENARIO 2

  • SCCP Phone-7941G, rtp-nte configured on gateway dial-peer

IPPhone--sccp--CUCM--SIP---Gateway---E1--PSTN

  • Gateway dial-peer config

dial-peer voice 3 voip

incoming called number .

no vad

dtmf-relay rtp-nte

I am going to skip the SIP signalling messages and go to the DTMF negotiation bit

Here we see the 200 OK sent to CUCM from the gateway and we see rtp-nte advertised in the SDP

16:59:41.964 |//SIP/SIPUdp/wait_UdpDataInd: Incoming SIP UDP message size 1119 from 172.10.104.32:[5060]:

[289744,NET]

SIP/2.0 200 OK

Via: SIP/2.0/UDP 172.10.40.11:5060;branch=z9hG4bK2348d9c6fccc

From: "Strand" <sip:02070043000@172.10.40.11>;tag=144444~ffa80926-5fac-4dd6-b405-2dbbc56ae9a2-392166160

To: <sip:908446930701@172.10.104.32>;tag=3BF6421A-410

Date: Mon, 20 May 2013 15:59:39 GMT

Call-ID: 45642d00-19a1486b-232d7-b28690a@172.10.40.11

CSeq: 101 INVITE

Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER

Allow-Events: telephone-event

Remote-Party-ID: <sip:08446930701@172.10.104.32>;party=called;screen=no;privacy=off

Contact: <sip:908446930701@172.10.104.32:5060>

Supported: replaces

Supported: sdp-anat

Server: Cisco-SIPGateway/IOS-12.x

Session-Expires: 84600;refresher=uac

Require: timer

Content-Type: application/sdp

Content-Disposition: session;handling=required

Content-Length: 273

v=0

o=CiscoSystemsSIP-GW-UserAgent 2394 1999 IN IP4 172.10.104.32

s=SIP Call

c=IN IP4 172.10.104.32

t=0 0

m=audio 18984 RTP/AVP 18 101

c=IN IP4 172.10.104.32

a=rtpmap:18 G729/8000

a=fmtp:18 annexb=no

a=rtpmap:101 telephone-event/8000

a=fmtp:101 0-16

a=ptime:20

Observe the DTMF capabilities on the SIP DTMF info

CUCM DTMF capabilites negotiation

16:59:42.037 |setLocalDtmfCaps: supportedDTMFMethod=3, mWantDtmfReception=1, mPeersWantDtmfReceptionFlag=0, mDtmfPreference=1|*^*^*

16:59:42.037 |SIP DTMF Info: mLocalDtmfCaps...UNSOL=1, KPML=1, Inband=1(101) mEndppointsDtmfCaps...UNSOL=0, KPML=0, Inband=1(101) mDefaultTelephonyEvent=101, mDtmfPreference=1, mMtpAllocated=0|*^*^*

Next we see the ACK sent by CUCM, which includes RFC2833/RFC4733

16:59:42.037 |//SIP/SIPUdp/wait_SdlSPISignal: Outgoing SIP UDP message to 172.10.104.32:[5060]:

[289745,NET]

ACK sip:908446930701@172.10.104.32:5060 SIP/2.0

Via: SIP/2.0/UDP 172.10.40.11:5060;branch=z9hG4bK2348e279e05fe

From: "Strand" <sip:02070043000@172.10.40.11>;tag=144444~ffa80926-5fac-4dd6-b405-2dbbc56ae9a2-392166160

To: <sip:908446930701@172.10.104.32>;tag=3BF6421A-410

Date: Mon, 20 May 2013 15:59:39 GMT

Call-ID: 45642d00-19a1486b-232d7-b28690a@172.10.40.11

Max-Forwards: 70

CSeq: 101 ACK

Allow-Events: presence, kpml

Content-Type: application/sdp

Content-Length: 236

v=0

o=CiscoSystemsCCM-SIP 144444 1 IN IP4 172.10.40.11

s=SIP Call

c=IN IP4 172.10.1.69

t=0 0

m=audio 29766 RTP/AVP 18 101

a=rtpmap:18 G729/8000

a=ptime:20

a=fmtp:18 annexb=no

a=rtpmap:101 telephone-event/8000

a=fmtp:101 0-15

As explained above we can see CUCM adverties rtp-nte , KPML and UNSOL (highlighted in green), where as the gateway only supports rtp-nte (set by dial-peer config)

Now we see the phone sending dtmf digits because dtmf is sent inband, cucm doesnt get involved in sending the digits
However in the sip stack we can still see the DTMF digits the endpoint is ending

++digit=0++

16:59:49.763 |//SIP/SIPD(22,73,28)/ccbId=0/scbId=0/getCdpcPid: found Cdpc Pid (22,100,74,268) for mapKey 392166160|23,100,13,72951.131^172.10.1.69^SEP5C5015A9D75B

16:59:49.763 |//SIP/SIPCdpc(22,74,268)/ci=392166160/ccbId=144444/scbId=0/star_CcUserInfoReq: Outbound DTMF method selected is 1. Digit=0 and isMTPPassingThru2833=0|23,100,13,72951.131^172.10.1.69^SEP5C5015A9D75B

++digits=2++

16:59:50.292 |//SIP/SIPD(22,73,28)/ccbId=0/scbId=0/getCdpcPid: found Cdpc Pid (22,100,74,268) for mapKey 392166160|23,100,13,72951.133^172.10.1.69^SEP5C5015A9D75B

16:59:50.292 |//SIP/SIPCdpc(22,74,268)/ci=392166160/ccbId=144444/scbId=0/star_CcUserInfoReq: Outbound DTMF method selected is 1. Digit=2 and isMTPPassingThru2833=0|23,100,13,72951.133^172.10.1.69^SEP5C5015A9D75B

On the gateway using debug voip rtp session named-event++ we can see the actual dtmf digits sent in RTP stream with payload 101

067897: .May 20 16:59:50.453 BST: s=VoIP d=DSP payload 0x65 ssrc 0x1DDD3867 sequence 0x60D timestamp 0xED976557

067898: .May 20 16:59:50.453 BST: <<<Rcv> Pt:101 Evt:0 Pkt:09 00 00

067899: .May 20 16:59:50.473 BST: s=VoIP d=DSP payload 0x65 ssrc 0x1DDD3867 sequence 0x60F timestamp 0xED976557

067900: .May 20 16:59:50.473 BST: <<<Rcv> Pt:101 Evt:0 Pkt:09 00 A0

067901: .May 20 16:59:50.493 BST: s=VoIP d=DSP payload 0x65 ssrc 0x1DDD3867 sequence 0x611 timestamp 0xED976557

067902: .May 20 16:59:50.493 BST: <<<Rcv> Pt:101 Evt:0 Pkt:09 01 40

067903: .May 20 16:59:50.513 BST: s=VoIP d=DSP payload 0x65 ssrc 0x1DDD3867 sequence 0x613 timestamp 0xED976557

067904: .May 20 16:59:50.513 BST: <<<Rcv> Pt:101 Evt:0 Pkt:89 01 E0

067905: .May 20 16:59:50.513 BST: s=VoIP d=DSP payload 0x65 ssrc 0x1DDD3867 sequence 0x614 timestamp 0xED976557

067906: .May 20 16:59:50.513 BST: <<<Rcv> Pt:101 Evt:0 Pkt:89 01 E0

067907: .May 20 16:59:50.533 BST: s=VoIP d=DSP payload 0x65 ssrc 0x1DDD3867 sequence 0x615 timestamp 0xED976557

067908: .May 20 16:59:50.533 BST: <<<Rcv> Pt:101 Evt:0 Pkt:89 01 E0

067909: .May 20 16:59:50.553 BST: s=VoIP d=DSP payload 0x65 ssrc 0x1DDD3867 sequence 0x623 timestamp 0xED976F57

067910: .May 20 16:59:50.553 BST: <<<Rcv> Pt:101 Evt:2 Pkt:09 00 00

067911: .May 20 16:59:50.573 BST: s=VoIP d=DSP payload 0x65 ssrc 0x1DDD3867 sequence 0x625 timestamp 0xED976F57

067912: .May 20 16:59:50.573 BST: <<<Rcv> Pt:101 Evt:2 Pkt:09 00 A0

067913: .May 20 16:59:50.593 BST: s=VoIP d=DSP payload 0x65 ssrc 0x1DDD3867 sequence 0x627 timestamp 0xED976F57

067914: .May 20 16:59:50.593 BST: <<<Rcv> Pt:101 Evt:2 Pkt:09 01 40

067915: .May 20 16:59:50.613 BST: s=VoIP d=DSP payload 0x65 ssrc 0x1DDD3867 sequence 0x629 timestamp 0xED976F57

067916: .May 20 16:59:50.613 BST: <<<Rcv> Pt:101 Evt:2 Pkt:09 01 E0

067917: .May 20 16:59:50.633 BST: s=VoIP d=DSP payload 0x65 ssrc 0x1DDD3867 sequence 0x62B timestamp 0xED976F57

067918: .May 20 16:59:50.633 BST: <<<Rcv> Pt:101 Evt:2 Pkt:89 02 80

067919: .May 20 16:59:50.633 BST: s=VoIP d=DSP payload 0x65 ssrc 0x1DDD3867 sequence 0x62C timestamp 0xED976F57

067920: .May 20 16:59:50.633 BST: <<<Rcv> Pt:101 Evt:2 Pkt:89 02 80

067921: .May 20 16:59:50.633 BST: s=VoIP d=DSP payload 0x65 ssrc 0x1DDD3867 sequence 0x62D timestamp 0xED976F57

067922: .May 20 16:59:50.633 BST: <<<Rcv> Pt:101 Evt:2 Pkt:89 02 80

SCENARIO 3:

  • Cisco 7941 with RFC2833 disabled, Exchange with rfc2833. (CUCM Inserts MTP to send rfc2833 out to exchange)

IPphone--SCCP--CUCM--------SIP-------Exchange Unified messaging

  • CUCM Logs

This is the 200 OK received from Exchange, here we see exchange advertising RFC2833/4733

00028171.006 |12:59:46.332 |AppInfo |SIPTcp - wait_SdlReadRsp: Incoming SIP TCP message from 192.168.131.40 on port 5065 index 377 with 1539 bytes:

[204,NET]

SIP/2.0 200 OK

FROM: "bob banks2"<sip:800193850@192.168.131.11>;tag=562~736dccb8-3be2-4f69-88f8-ec5946dd6872-27034350

TO: <sip:755670001@192.168.131.40>;tag=3c42c6b9c1;epid=4F9342F874

CSEQ: 101 INVITE

CALL-ID: 6aa02a80-1a713f32-1e3-b83a8c0@192.168.131.11

VIA: SIP/2.0/TCP 192.168.131.11:5060;branch=z9hG4bK1f51b101ed3

CONTACT: <sip:UCLAB-DC.uclab.com:5065;transport=Tcp;maddr=192.168.131.40>;automata;text;audio;video;image

CONTENT-LENGTH: 678

PRIORITY: Normal

SUPPORTED: Replaces

SUPPORTED: timer

SUPPORTED: 100rel

CONTENT-TYPE: application/sdp

ALLOW: ACK

P-ASSERTED-IDENTITY: <sip:755670001@192.168.131.40>

SERVER: RTCC/3.5.0.0 MSExchangeUM/14.01.0218.012

Content-ID: af19ca95-d81b-413e-8657-f90d5ea9b4aa

Allow: CANCEL,BYE,INVITE,MESSAGE,INFO,SERVICE,OPTIONS,BENOTIFY,NOTIFY,PRACK,UPDATE

Session-Expires: 1800;refresher=uac

Min-SE: 1800

v=0

o=- 11 0 IN IP4 192.168.131.40

s=session

c=IN IP4 192.168.131.40

b=CT:1000

t=0 0

m=audio 32764 RTP/AVP 114 115 112 111 116 3 4 0 8 13 118 97 101

c=IN IP4 192.168.131.40

a=rtcp:32765

a=sendrecv

a=label:main-audio

a=rtpmap:114 x-msrta/16000

a=fmtp:114 bitrate=29000

a=rtpmap:115 x-msrta/8000

a=fmtp:115 bitrate=11800

a=rtpmap:112 G7221/16000

a=fmtp:112 bitrate=24000

a=rtpmap:111 SIREN/16000

a=fmtp:111 bitrate=16000

a=rtpmap:116 AAL2-G726-32/8000

a=rtpmap:3 GSM/8000

a=rtpmap:4 G723/8000

a=rtpmap:0 PCMU/8000

a=rtpmap:8 PCMA/8000

a=rtpmap:13 CN/8000

a=rtpmap:118 CN/16000

a=rtpmap:97 RED/8000

a=rtpmap:101 telephone-event/8000

a=fmtp:101 0-16,36

NB: From the CUCM logs we can see that CUCM DTMF info does not yet indicate that its going to do RFC2833. This is because CUCM will not send support for rfc2833 untill it allocates an MTP since the endpoint cant do rfc2833.

00028195.006 |12:59:46.337 |AppInfo |SIP DTMF Info: mLocalDtmfCaps...UNSOL=1, KPML=1, Inband=0(0) mEndppointsDtmfCaps...UNSOL=0, KPML=0, Inband=1(101) mDefaultTelephonyEvent=101, mDtmfPreference=1, mMtpAllocated=0

Next CUCM says we need MTP due to DTMF mistmatch

00028211.015 |12:59:46.338 |AppInfo |DET-MediaManager-(13)::isMTPNeededForMismatchOrConfig, MTPNeededDueToDTMFCapMismatch(2833/OOB) mtpinsertionReason=1 dtmfMTPSide=2

Next CUCM Allocates an MTP Resource

00028219.020 |12:59:46.339 |AppInfo |MediaTerminationPointControl(1)::getResourcesAllocated -- DeviceName=MTP_2 Ci=27034351 ResourceAllocated=1

Next We see CUCM updates its DTMF info and we see RFC2833/4733 advertised

00028362.002 |12:59:46.524 |AppInfo |SIP DTMF Info: mLocalDtmfCaps...UNSOL=1, KPML=1, Inband=1(101) mEndppointsDtmfCaps...UNSOL=0, KPML=0, Inband=1(101) mDefaultTelephonyEvent=101, mDtmfPreference=1, mMtpAllocated=1

Next CUCM sends an ACK advertising rtp-nte

Observe that the ip address of CUCM is where media is sent to (look at the connection parameter)

00028384.001 |12:59:46.526 |AppInfo |SIPTcp - wait_SdlSPISignal: Outgoing SIP TCP message to 192.168.131.40 on port 5065 index 377

[205,NET]

ACK sip:UCLAB-DC.uclab.com:5065;maddr=192.168.131.40;transport=Tcp SIP/2.0

Via: SIP/2.0/TCP 192.168.131.11:5060;branch=z9hG4bK1f61b97d076

From: "bob banks2" <sip:800193850@192.168.131.11>;tag=562~736dccb8-3be2-4f69-88f8-ec5946dd6872-27034350

To: <sip:755670001@192.168.131.40>;tag=3c42c6b9c1

Date: Thu, 30 May 2013 11:59:46 GMT

Call-ID: 6aa02a80-1a713f32-1e3-b83a8c0@192.168.131.11

Max-Forwards: 70

CSeq: 101 ACK

Allow-Events: presence, kpml

Content-Type: application/sdp

Content-Length: 224

v=0

o=CiscoSystemsCCM-SIP 562 1 IN IP4 192.168.131.11

s=SIP Call

c=IN IP4 192.168.131.11

b=CT:64

t=0 0

m=audio 24584 RTP/AVP 8 101

a=rtpmap:8 PCMA/8000

a=ptime:20

a=rtpmap:101 telephone-event/8000

a=fmtp:101 0-15

NEXT we see the DTMF digit pressed on the phone

++digit pressed=1++

00028404.001 |12:59:51.296 |AppInfo |StationInit: (0000006) KeypadButton kpButton=1

Next CUCM chooses the outbound method to use to send the digit

From my experience, here are the DTMF methods you will see in CUCM traces

  • RFC2833--- Outbound DTMF method = 1

  • OOB---RFC2833-- Outbound DTMF method=2

  • KPML---- Outbound DTMF method=3

00028412.001 |12:59:51.297 |AppInfo |SIPCdpc(11) - star_CcUserInfoReq: Outbound DTMF method selected is 2. Digit=1 and isMTPPassingThru2833=0

00028412.002 |12:59:51.297 |AppInfo |SIPCdpc(11) - sendDtmfVia2833: sending sipOutgoingDTMFTone Tone 1 for digit 1.

Next we see MTP receiving dtmf pressed on the phone, NB the phone sending the digit and trhe digit sent

00028416.000 |12:59:51.297 |SdlSig |MXOutgoingDTMFTone |waiting |MediaTerminationPointControl(1,100,130,1) |MTPAgenaInterface(1,100,233,6) |1,100,13,79.26^192.168.131.60^SEP001BD584B00D |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0] tone=1 CI=27034351 confId=16779219 passthruPartyID=0x1000013 isMTPPassingThru2833=F

Here we see the MTP process on CUCM sending tone=1 out to exhchange

00028416.001 |12:59:51.297 |AppInfo |MediaTerminationPointControl(1)::star_MediaExchangeOutgoingDTMFTone tone=1, conferenceID=16779219, passthruID=16777235

00028416.002 |12:59:51.297 |AppInfo |MediaTerminationPointControl(1)::star_MediaExchangeOutgoingDTMFTone TCPPid = [1.100.13.4] myIP: 0xb83a8c0 (192.168.131.11) conferenceID=16779219, passthruPartyID=16777235, tone=1

Next we see another digit (2) pressed on the phone

00028424.001 |12:59:51.808 |AppInfo |StationInit: (0000006) KeypadButton kpButton=2.

00028432.001 |12:59:51.808 |AppInfo |SIPCdpc(11) - star_CcUserInfoReq: Outbound DTMF method selected is 2. Digit=2 and isMTPPassingThru2833=0

00028432.002 |12:59:51.808 |AppInfo |SIPCdpc(11) - sendDtmfVia2833: sending sipOutgoingDTMFTone Tone 2 for digit 2

Next we see MTP receiving dtmf pressed on the phone, NB the phone sending the digit and trhe digit sent

00028436.000 |12:59:51.808 |SdlSig |MXOutgoingDTMFTone |waiting |MediaTerminationPointControl(1,100,130,1) |MTPAgenaInterface(1,100,233,6) |1,100,13,79.27^192.168.131.60^SEP001BD584B00D |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0] tone=2 CI=27034351 confId=16779219 passthruPartyID=0x1000013 isMTPPassingThru2833=F

Here we see the MTP process on CUCM sending tone=2 out

00028436.001 |12:59:51.808 |AppInfo |MediaTerminationPointControl(1)::star_MediaExchangeOutgoingDTMFTone tone=2, conferenceID=16779219, passthruID=16777235

00028436.002 |12:59:51.808 |AppInfo |MediaTerminationPointControl(1)::star_MediaExchangeOutgoingDTMFTone TCPPid = [1.100.13.4] myIP: 0xb83a8c0 (192.168.131.11) conferenceID=16779219, passthruPartyID=16777235, tone=2

We can also take wiresshark captures from CUCM and we will see the actual "rtpevent" sent out and the digits sent. The screen shot below shows the wireshark cpatures taking from CUCM and the RFC2833 formatted digits sent out to exchange.

From the wireshark traces, we can see the digit been sent out by the MTP to the exchange server.

wiresharktrace.jpg

SCENARIO 4:

  • Cisco Jabber for windows, SIP-KPML and rtp-nte configured on gateway dial-peer

jabber4windows--SIP---CUCM--SIP---Gateway---E1--PSTN

  • Gateway dial-peer config

dial-peer voice 3 voip

incoming called number .

no vad

dtmf-relay sip-kpml rtp-nte

Here we can see that both endpoint support KPML and rtp-nte

14:53:48.445 |setEndpointsDtmfCaps: KPML Supported.|*^*^*

14:53:48.445 |setEndpointsDtmfCaps: Detected inband DTMF support.|*^*^*

14:53:48.445 |SIP DTMF Info: mLocalDtmfCaps...UNSOL=1, KPML=1, Inband=1(101) mEndppointsDtmfCaps...UNSOL=0, KPML=1, Inband=1(101) mDefaultTelephonyEvent=101, mDtmfPreference=1, mMtpAllocated=0|*^*^*

When both endpoint support rtp-nte regardless of the dtmf preference configured on the gateway, RTP-NTE will be negotiated and used

DTMF DIGITS

++ digit=0 ++

14:53:58.898 |//SIP/SIPD(22,73,33)/ccbId=0/scbId=0/getCdpcPid: found Cdpc Pid (22,100,74,286) for mapKey 544627160|23,100,63,1.1271^172.10.40.190^*

14:53:58.898 |//SIP/SIPCdpc(22,74,286)/ci=544627160/ccbId=155570/scbId=0/star_CcUserInfoReq: Outbound DTMF method selected is 1. Digit=0 and isMTPPassingThru2833=0|23,100,63,1.1271^172.10.40.190^*

++ digit=2 ++

14:54:01.948 |//SIP/SIPD(22,73,33)/ccbId=0/scbId=0/getCdpcPid: found Cdpc Pid (22,100,74,286) for mapKey 544627160|23,100,63,1.1272^172.10.40.190^*

14:54:01.948 |//SIP/SIPCdpc(22,74,286)/ci=544627160/ccbId=155570/scbId=0/star_CcUserInfoReq: Outbound DTMF method selected is 1. Digit=2 and isMTPPassingThru2833=0|23,100,63,1.1272^172.10.40.190^*

Here we see the rtp event received on the gateway

082055: May 24 14:53:58.743 BST: s=VoIP d=DSP payload 0x65 ssrc 0xDCC07A11 sequence 0x3B6B timestamp 0xA892DC55

082056: May 24 14:53:58.743 BST: <<<Rcv> Pt:101 Evt:0 Pkt:0A 01 90

082057: May 24 14:53:58.793 BST: s=VoIP d=DSP payload 0x65 ssrc 0xDCC07A11 sequence 0x3B6C timestamp 0xA892DC55

082058: May 24 14:53:58.793 BST: <<<Rcv> Pt:101 Evt:0 Pkt:0A 01 90

082059: May 24 14:53:58.843 BST: s=VoIP d=DSP payload 0x65 ssrc 0xDCC07A11 sequence 0x3B6D timestamp 0xA892DC55

082060: May 24 14:53:58.843 BST: <<<Rcv> Pt:101 Evt:0 Pkt:0A 03 20

082061: May 24 14:53:58.893 BST: s=VoIP d=DSP payload 0x65 ssrc 0xDCC07A11 sequence 0x3B6E timestamp 0xA892DC55

082062: May 24 14:53:58.893 BST: <<<Rcv> Pt:101 Evt:0 Pkt:0A 04 B0

082063: May 24 14:53:58.943 BST: s=VoIP d=DSP payload 0x65 ssrc 0xDCC07A11 sequence 0x3B6F timestamp 0xA892DC55

082064: May 24 14:53:58.943 BST: <<<Rcv> Pt:101 Evt:0 Pkt:0A 06 40

082065: May 24 14:53:58.993 BST: s=VoIP d=DSP payload 0x65 ssrc 0xDCC07A11 sequence 0x3B70 timestamp 0xA892DC55

082066: May 24 14:53:58.993 BST: <<<Rcv> Pt:101 Evt:0 Pkt:8A 07 D0

082067: May 24 14:54:01.800 BST: s=VoIP d=DSP payload 0x65 ssrc 0xDCC07A11 sequence 0x3BFB timestamp 0xA8933BD5

082068: May 24 14:54:01.800 BST: <<<Rcv> Pt:101 Evt:2 Pkt:0A 01 90

082069: May 24 14:54:01.848 BST: s=VoIP d=DSP payload 0x65 ssrc 0xDCC07A11 sequence 0x3BFC timestamp 0xA8933BD5

082070: May 24 14:54:01.848 BST: <<<Rcv> Pt:101 Evt:2 Pkt:0A 01 90

082071: May 24 14:54:01.900 BST: s=VoIP d=DSP payload 0x65 ssrc 0xDCC07A11 sequence 0x3BFD timestamp 0xA8933BD5

082072: May 24 14:54:01.900 BST: <<<Rcv> Pt:101 Evt:2 Pkt:0A 03 20

082073: May 24 14:54:01.950 BST: s=VoIP d=DSP payload 0x65 ssrc 0xDCC07A11 sequence 0x3BFE timestamp 0xA8933BD5

082074: May 24 14:54:01.950 BST: <<<Rcv> Pt:101 Evt:2 Pkt:0A 04 B0

082075: May 24 14:54:02.000 BST: s=VoIP d=DSP payload 0x65 ssrc 0xDCC07A11 sequence 0x3BFF timestamp 0xA8933BD5

082076: May 24 14:54:02.000 BST: <<<Rcv> Pt:101 Evt:2 Pkt:0A 06 40

082077: May 24 14:54:02.050 BST: s=VoIP d=DSP payload 0x65 ssrc 0xDCC07A11 sequence 0x3C00 timestamp 0xA8933BD5

082078: May 24 14:54:02.050 BST: <<<Rcv> Pt:101 Evt:2 Pkt:8A 07 D0

Hence we see that even though sip-kpml was the preffered method on the dial-peer rtp-nte was used..As long as both endpoints support it, it will be used

For more troubleshooting tips, please refer to this excellent post from Lavanya

https://supportforums.cisco.com/community/netpro/collaboration-voice-video/ip-telephony/blog/2013/05/27/understanding-sip-dtmf-options-supported-by-cucm

Version history
Revision #:
1 of 1
Last update:
‎06-06-2013 06:55 AM
Updated by:
 
Labels (1)
Comments

As always excellent document ! Very Informative.

Regards

Lavanya

New Member

You have done really well to have created this doc. Truly a hard working guy.

Great Job!

VIP Super Bronze

Thank you my brother. Kind words from you

Cisco Employee

I have come across this doc many times, made sure to rate it this time for the excellent work.

Manish

VIP Super Bronze

Thank you Manish. Really appreciate the feedback.

VIP Silver

Great Doc.thanks

New Member

What a great article! You are the man of honor! I wish I could  be as great person as you are. You truly inspired me.

Regards,

Moshfiqur

VIP Super Bronze

Moshfiqur,

Thank you for the nice compliment, I really appreciate it.

Regards