[cisco-voip] SIP call issue, call get connected after 10 sec.

Wed Apr 2 02:48:53 EDT 2014

Hi Brian,

As what we have seen that MGCP gateway did not even received all the digits pressed by the user.

However debug ccapi inout is showing that it's relaying the digit (twice).

however the MGCP gateway is not able to catch that.

Attached is the log for the same.

Please suggest.

Kind Regards,
Raaj.

________________________________
 From: Brian Meade <bmeade90 at vt.edu>
To: Rajkumar Yadav <rajkumaryadav at y7mail.com> 
Cc: Amit Kumar <amit3.kum at gmail.com>; "Heim, Dennis" <Dennis.Heim at wwt.com>; "cisco-voip at puck.nether.net" <cisco-voip at puck.nether.net> 
Sent: Tuesday, 1 April 2014 8:15 PM
Subject: Re: [cisco-voip] SIP call issue, call get connected after 10 sec.

Raaj,

I looked at these traces and see the MTP is being pulled in due to the early offer configuration but would also be needed for the DTMF mismatch:
20:20:05.285 |MediaManager(710186)::wait_AuConnectRequest, CI(48708178,48708179), capCount(11,1), mcNodeId(0,0), xferMode(12,16), reConnectType(0), mrid (0, 0) IFCreated(0 0) proIns(0 0), AC(0,0) party1DTMF(1 1 0 1 0) party2DTMF(3 2 101 1 0),reConnFlag=0, connType(3,3), IFHand(0,0),MTP(0,0),MRGL(aaf6462d-d96d-8d78-e98b-f96a899cd470,aaf6462d-d96d-8d78-e98b-f96a899cd470) videoCap(0 0), mmCallType(0),FS(0,0) IpAddrMode(0 0) aPid(2, 135, 1366), bPid(2, 68, 209650) EOType(0 2)|2,100,57,1.1030654^10.14.0.46^*

20:20:05.285 |MediaManager(710186)::isMTPNeededForDTMF, isMTPNeeded(1)|2,100,57,1.1030654^10.14.0.46^*

party1 only supports out of band and party 2 only supports in-band.  It looks like the SIP Trunk has a DTMF Preference hard set as well.

As far as only getting 1 digit, I only see one digit actually being sent by the MGCP gateway:
20:20:11.021 |MGCPHandler received msg from: 10.128.0.2
NTFY 200530244 S0/SU0/DS1-0/11 at 10.128.0.2 MGCP 0.1
N: ca at 10.128.4.10:2427
X: b
O: D/1
|2,100,152,1.5777096^10.128.0.2^*

CUCM sends a request notification to continue receiving any future digits:
20:20:11.022 |MGCPHandler send msg SUCCESSFULLY to: 10.128.0.2
RQNT 1863107 S0/SU0/DS1-0/11 at 10.128.0.2 MGCP 0.1
X: b
R: D/[0-9ABCD*#]
Q: process,loop

But the gateway never seems to send any further digits.

Brian

On Tue, Apr 1, 2014 at 2:13 AM, Rajkumar Yadav <rajkumaryadav at y7mail.com> wrote:

Hi Brian,
>
>
>I got the traces  for the call without MTP checked.
>
>
>The call went good but the DTMF issue came up.
>
>
>Please find the attched logs.
>
>
>
>
>20:20:04.259 |//SIP/SIPCdpc(2,68,209650)/ci=48708179/ccbId=943721/scbId=0/StartTransition: requireInactiveSDPForMidcallMediaChange=0, isTrunkEnabledForVoiceEO=1|2,100,68,209650.1^*^*
>
>
>
>Here the EO is working due to the SIP profile for that SIP trunk having EO provisioned and MTP unchecked.
>
>
>
>
>
>
>20:20:04.259 |MediaUtility::isMTPNeededForDTMFBeforeCutThru, there is DTMF MISMATCH, party1SuppDTMFMethod=1 party2DtmfConfig=3|*^*^*
>
>
>
> In the traces the MTP is allocated too.
>
>
>20:20:04.261 |MRM::updateMtpCounter devName=MTP_3, countChange=1|2,100,153,1.1418009^10.128.0.2^*
>20:20:04.261 |MRM::updateXcodeCounter devName=MTP_3, countChange=1|2,100,153,1.1418009^10.128.0.2^*
>
>
>
>
>
>
>However as per the person having issue that only Digit 1 is passed on to the IVR system (SIP phone) and rest 8 digits are not.
>
>
>
>
>DTMFMTPSide(1), mtpNeededForDtmf(1) firstconnDTMF(2) secondconnDTMF(1)|2,100,57,1.1030654^10.14.0.46^*
>20:20:05.285 |MediaManager(710186)::needToInjectDigitsToMTP, isMTPNeededDueToDTMFCapMismatch dtmfMTPSide(1)index(0) injecttoMTP(1)|2,100,57,1.1030654^10.14.0.46^*
>20:20:05.285 |MediaManager(710186)::can2833beNegotiatedForCall, --2833 can nto be negotiated for the call|2,100,57,1.1030654^10.14.0.46^*
>20:20:05.285 |MediaManager(710186)::setSubscriptionInfo, subscribe(1), passthru(0), inject(1) index(0)|2,100,57,1.1030654^10.14.0.46^*
>20:20:05.285 |MediaManager(710186)::allocatedMtpSupportsAnyDtmfCapability|2,100,57,1.1030654^10.14.0.46^*
>20:20:05.285 |MediaManager(710186)::DTMFMTPSide(1), mtpNeededForDtmf(1) firstconnDTMF(2) secondconnDTMF(1)|2,100,57,1.1030654^10.14.0.46^*
>20:20:05.285 |MediaManager(710186)::needToInjectDigitsToMTP, isMTPNeededDueToDTMFCapMismatch dtmfMTPSide(1)index(1) injecttoMTP(0)|2,100,57,1.1030654^10.14.0.46^*
>20:20:05.285 |MediaManager(710186)::can2833beNegotiatedForCall, --2833 can nto be negotiated for the call|2,100,57,1.1030654^10.14.0.46^*
>
>
>
>
>Please suggest and have a look into the traces for more detail.
>
>
>Kind Regards,
>Raaj.
>
>
>
>
>
>________________________________
> From: Brian Meade <bmeade90 at vt.edu>
>To: Rajkumar Yadav <rajkumaryadav at y7mail.com> 
>Cc: Amit Kumar <amit3.kum at gmail.com>; "Heim, Dennis" <Dennis.Heim at wwt.com>; "cisco-voip at puck.nether.net" <cisco-voip at puck.nether.net> 
>Sent: Monday, 31 March 2014 7:07 PM
>
>Subject: Re: [cisco-voip] SIP call issue, call get connected after 10 sec.
>
>
>
>Raaj,
>
>
>CUCM should dynamically insert an MTP when needed for a DTMF mismatch.  Would probably need to investigate what is happening when you leave MTP Required unchecked.
>
>
>MTP Required overrides the normal Early Offer process when turned on via the SIP Profile on the trunk.  It still results in an Early Offer invite though but through a different process.
>
>
>Brian
>
>
>
>On Mon, Mar 31, 2014 at 12:07 AM, Rajkumar Yadav <rajkumaryadav at y7mail.com> wrote:
>
>we do had unchecked the MTP and tested the call, all calls were properly treated.
>>
>>
>>However the DTMF issue came up, since the Genesys side SIP softphone is supporting only inband (RFC 2833) and MGCP gateway would be configured with OOB DTMF method.
>>
>>
>>(since SCCP phone support both DTMF method can we change the dtmf method in MGCP gateway itself)
>>
>>
>>Also from the traces it fails to do EO due to configuration issue.
>>
>>
>>16:15:17.424 |//SIP/SIPCdpc(2,68,205069)/ci=48665604/ccbId=918923/scbId=0/isTrunkConfiguredforVoiceEO: Trunk configured for EO but EO will not be effective due to other configuration - MTPRequired=1 IPAddrMode=0 MediaPreference=0|2,100,68,205069.1^*^*
>>
>>
>>
>>
>>
>>
>>
>>
>>
>>Kind Regards,
>>Raaj
>>
>>
>>
>>
>>
>>
>>
>>________________________________
>> From: Brian Meade <bmeade90 at vt.edu>
>>To: Amit Kumar <amit3.kum at gmail.com> 
>>Cc: "Heim, Dennis" <Dennis.Heim at wwt.com>; "cisco-voip at puck.nether.net" <cisco-voip at puck.nether.net>; Rajkumar Yadav <rajkumaryadav at y7mail.com> 
>>Sent: Monday, 31 March 2014 9:12 AM
>>Subject: Re: [cisco-voip] SIP call issue, call get connected after 10 sec.
>> 
>>
>>
>>The only difference I was able to find between the working and nonworking is that the Create Connection Response is received before the outgoing invite in the working scenario:
>>Create Connection:
>>16:15:17.423 |MGCPHandler send msg SUCCESSFULLY to: 10.128.0.2
>>CRCX 1822574 S0/SU0/DS1-0/11 at 10.128.0.2 MGCP 0.1
>>C: D000000002e69403000000F58000051d
>>X: b
>>L: p:20, a:PCMU, s:off, t:b8
>>M: recvonly
>>R: D/[0-9ABCD*#]
>>Q: process,loop
>>|2,100,153,1.1390558^10.128.0.2^*
>>
>>
>>Create Connection Response:
>>16:15:17.433 |MGCPHandler received msg from: 10.128.0.2
>>200 1822574 OK
>>I: D2D7
>>
>>
>>v=0
>>c=IN IP4 10.128.0.2
>>m=audio 19388 RTP/AVP 0 100
>>a=rtpmap:100 X-NSE/8000
>>a=fmtp:100 192-194,200-202
>>a=X-sqn:0
>>a=X-cap: 1 audio RTP/AVP 100
>>a=X-cpar: a=rtpmap:100 X-NSE/8000
>>a=X-cpar: a=fmtp:100 192-194,200-202
>>a=X-cap: 2 image udptl t38
>>|2,100,152,1.5650860^10.128.0.2^*
>>
>>
>>Outgoing Invite:
>>16:15:17.468 |//SIP/SIPTcp/wait_SdlSPISignal: Outgoing SIP TCP message to 10.14.0.46 on port 5460 index 2245 
>>[3153414,NET]
>>INVITE sip:2600 at 10.14.0.46:5460 SIP/2.0
>>Via: SIP/2.0/TCP 10.128.4.10:5060;branch=z9hG4bK9ddfe2fc1b6c2
>>From: <sip:226241315 at 10.128.4.10>;tag=918923~30427db0-275c-441d-b31f-5c77cf1a9379-48665604
>>To: <sip:2600 at 10.14.0.46>
>>Date: Sat, 29 Mar 2014 20:15:17 GMT
>>Call-ID: d6d8fe00-337129d5-34100-a04800a at 10.128.4.10
>>Supported: timer,resource-priority,replaces
>>Min-SE:  1800
>>User-Agent: Cisco-CUCM8.5
>>Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY
>>CSeq: 101 INVITE
>>Expires: 300
>>Allow-Events: presence
>>Supported: X-cisco-srtp-fallback
>>Supported: Geolocation
>>Cisco-Guid: 3604545024-0000065536-0000204906-0168067082
>>Session-Expires:  1800
>>P-Asserted-Identity: <sip:226241315 at 10.128.4.10>
>>Remote-Party-ID: <sip:226241315 at 10.128.4.10>;party=calling;screen=yes;privacy=off
>>Contact: <sip:226241315 at 10.128.4.10:5060;transport=tcp>
>>Max-Forwards: 70
>>Content-Type: application/sdp
>>Content-Length: 210
>>
>>
>>v=0
>>o=CiscoSystemsCCM-SIP 2000 1 IN IP4 10.128.4.10
>>s=SIP Call
>>c=IN IP4 10.128.4.10
>>t=0 0
>>m=audio 28102 RTP/AVP 0 101
>>a=rtpmap:0 PCMU/8000
>>a=ptime:20
>>a=rtpmap:101 telephone-event/8000
>>a=fmtp:101 0-15
>>
>>
>>
>>
>>Here's what the nonworking looks like:
>>Create Connection:
>>16:17:47.391 |MGCPHandler send msg SUCCESSFULLY to: 10.128.4.12
>>CRCX 1822579 S0/SU3/DS1-0/14 at 10.128.4.12 MGCP 0.1
>>C: D000000002e69406000000F58000048a
>>X: e
>>L: p:20, a:PCMU, s:off, t:b8
>>M: recvonly
>>R: D/[0-9ABCD*#]
>>Q: process,loop
>>|2,100,153,1.1390562^10.128.4.12^*
>>
>>
>>OpenLogicalChannelAck from MTP:
>>383984245 |2014/03/29 16:17:47.406 |100 |SdlSig-I  |MXAgenaOpenLogicalChannelAck           |outCall_waitOLCAck             |SIPCdpc(2,100,68,205070)         |MediaTerminationPointControl(1,100,122,3) |1,100,50,1.79616142^10.128.4.10^MTP_3    |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0] rc=0 partyId=34213137 port=28106 ipAddrType=0 ipv4=10.128.4.10
>>
>>
>>Outgoing invite with a=inactive:
>>16:17:47.407 |//SIP/SIPTcp/wait_SdlSPISignal: Outgoing SIP TCP message to 10.14.0.46 on port 5460 index 2245 
>>[3153448,NET]
>>INVITE sip:2600 at 10.14.0.46:5460 SIP/2.0
>>Via: SIP/2.0/TCP 10.128.4.10:5060;branch=z9hG4bK9de045e6642c
>>From: <sip:226241315 at 10.128.4.10>;tag=918936~30427db0-275c-441d-b31f-5c77cf1a9379-48665607
>>To: <sip:2600 at 10.14.0.46>
>>Date: Sat, 29 Mar 2014 20:17:47 GMT
>>Call-ID: 30412d00-33712a6b-34104-a04800a at 10.128.4.10
>>Supported: timer,resource-priority,replaces
>>Min-SE:  1800
>>User-Agent: Cisco-CUCM8.5
>>Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY
>>CSeq: 101 INVITE
>>Expires: 300
>>Allow-Events: presence
>>Supported: X-cisco-srtp-fallback
>>Supported: Geolocation
>>Cisco-Guid: 0809577728-0000065536-0000204907-0168067082
>>Session-Expires:  1800
>>P-Asserted-Identity: <sip:226241315 at 10.128.4.10>
>>Remote-Party-ID: <sip:226241315 at 10.128.4.10>;party=calling;screen=yes;privacy=off
>>Contact: <sip:226241315 at 10.128.4.10:5060;transport=tcp>
>>Max-Forwards: 70
>>Content-Type: application/sdp
>>Content-Length: 222
>>
>>
>>v=0
>>o=CiscoSystemsCCM-SIP 2000 1 IN IP4 10.128.4.10
>>s=SIP Call
>>c=IN IP4 10.128.4.10
>>t=0 0
>>m=audio 28106 RTP/AVP 0 101
>>a=rtpmap:0 PCMU/8000
>>a=ptime:20
>>a=inactive
>>a=rtpmap:101 telephone-event/8000
>>a=fmtp:101 0-15
>>
>>
>>Create connection response comes after this:
>>16:17:47.408 |MGCPHandler received msg from: 10.128.4.12
>>200 1822579 OK
>>I: 1430EE
>>
>>
>>v=0
>>c=IN IP4 10.128.4.12
>>m=audio 18048 RTP/AVP 0 100
>>a=rtpmap:100 X-NSE/8000
>>a=fmtp:100 192-194
>>
>>
>>It could be a potential race condition.  He's running 8.5.1 base so definitely huge bug potential here.  I found https://tools.cisco.com/bugsearch/bug/CSCtk77040 which seems to be a good match based on the conditions.  I would try getting rid of the MTP Required on the SIP Trunk and see if that resolves the issue.  If so, you should probably upgrade to the latest 8.5.1 SU if you need to send Early Media.
>>
>>
>>-Brian Meade
>>
>>
>>
>>On Sun, Mar 30, 2014 at 3:38 PM, Amit Kumar <amit3.kum at gmail.com> wrote:
>>
>>Seems to be 8.5.1 , 16:11:57.327 HDR|03/29/2014 CCM,StandAloneCluster,10.128.4.10,Detailed,8.5.1.10000-26|*^*^*
>>>16:11:57.327 |
>>>
>>>checking traces Raj
>>>
>>>
>>>
>>>
>>>On Sun, Mar 30, 2014 at 11:18 PM, Heim, Dennis <Dennis.Heim at wwt.com> wrote:
>>>
>>>CUCM version is?
>>>> 
>>>>Dennis Heim | Solution Architect (Collaboration)
>>>>World Wide Technology, Inc. | 314-212-1814
>>>> 
>>>>PS Engineering:  Innovate & Ignite.
>>>> 
>>>> 
>>>>From:cisco-voip [mailto:cisco-voip-bounces at puck.nether.net] On Behalf Of Rajkumar Yadav
>>>>Sent: Sunday, March 30, 2014 3:16 AM
>>>>To: cisco-voip at puck.nether.net
>>>>Subject: [cisco-voip] SIP call issue, call get connected after 10 sec.
>>>> 
>>>>Hi,
>>>> 
>>>>Please kind request to help me for the attached logs.
>>>> 
>>>>setup is like this 
>>>> 
>>>>PSTN--MGCP---CUCM--SIP Trunk--Genesys Contact center.
>>>> 
>>>>Option selected in SIP trunk is MTP checked (DTMF interoperabiltiy), from SIP profile Early offer.
>>>> 
>>>>Issue is sometime call goes good and sometime call connected after 10 sec.
>>>> 
>>>>We get media inactive and reinvite makes the connection goes good.
>>>> 
>>>>For good call     Call-ID: d6d8fe00-337129d5-34100-a04800a at 10.128.4.10
>>>> 
>>>>For Bad call       Call-ID: 30412d00-33712a6b-34104-a04800a at 10.128.4.10
>>>> 
>>>>Kind Regards,
>>>>Raaj.
>>>> 
>>>> 
>>>>_______________________________________________
>>>>cisco-voip mailing list
>>>>cisco-voip at puck.nether.net
>>>>https://puck.nether.net/mailman/listinfo/cisco-voip
>>>>
>>>>
>>>>
>>>
>>>
>>>
>>>_______________________________________________
>>>cisco-voip mailing list
>>>cisco-voip at puck.nether.net
>>>https://puck.nether.net/mailman/listinfo/cisco-voip
>>>
>>>
>>
>>
>>
>>
>
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://puck.nether.net/pipermail/cisco-voip/attachments/20140401/99260da5/attachment.html>
-------------- next part --------------
An embedded and charset-unspecified text was scrubbed...
Name: ccapi.txt
URL: <https://puck.nether.net/pipermail/cisco-voip/attachments/20140401/99260da5/attachment.txt>