Disconnect Calls from CUCM 8.6 to Lync - MRM::waiting_AllocateMtpResourceErr - ERROR - no resources ...

massimiliano.mariani1 · ‎08-25-2017

Hello,

Calls from CUCM towards Lync Response Group fails with a Normal Call Clearing from CUCM. SIP traces show that when it fails, CUCM doesn't ACK the 200OK with SDP session; instead call towards single Lync user works properly and CUCM sends ACK after having received 200OK. CUCM logs files, during KO scenario, show following error, even if MTP on trunk was disabled:

MRM::waiting_AllocateMtpResourceErr - ERROR - no resources are available

Attached the SIP traces (Ok & KO).

Thanks in advance

Max

Abhay Singh Reyal · ‎08-29-2017

Reproduce the issue and Collect the CUCM traces [Detailed] for 5 mins. Provide below
Calling Number
Called Number
Time Stamp

Regards
Abhay

Regards
Abhay Singh Reyal
The Only Way To Do Great Work Is To Love What You Do. If You Haven’t Found It Yet, Keep Looking. Don’t Settle

massimiliano.mariani1 · ‎08-29-2017

Hello Abhay,

CCM SDI logs collected already on subscribers for about 10 minutes, let me try to enclose you:

Calling Number 03371444693

Called 7069170

Time Stamp 17:00:13 seconds (more or less)

Thanks in advance

Max

Abhay Singh Reyal · ‎08-30-2017

1st Call Leg :- d4886500-99d1989b-2414e-721516ac@172.22.21.114
2nd Call Leg :- d4886500-99d1989b-3b85b1-282e16ac@172.22.46.40

CUCM received PriQsigSetupMsg for the no. 71887069170
++++++
17:00:43.519 |In Message -- PriQsigSetupMsg -- Protocol= PriQsigProtocol|*^*^*
17:00:43.519 |Ie - Ni2BearerCapabilityIe -- IEData= 04 03 80 90 A3 |*^*^*
17:00:43.519 |Ie - Q931ChannelIdIe -- IEData= 18 03 A9 83 81 |*^*^*
17:00:43.519 |Ie - Q931CallingPartyIe -- IEData= 6C 0D 00 83 30 33 33 37 31 34 34 34 36 39 33 |*^*^*
17:00:43.519 |Ie - Q931CalledPartyIe -- IEData= 70 0C 80 37 31 38 38 37 30 36 39 31 37 30 |*^*^*
17:00:43.519 |MMan_Id= 0. (iep= 0 dsl= 0 sapi= 0 ces= 0 IpAddr=0 IpPort=0)|*^*^*

Initial Incoming Invite to CUCM
++++++
17:00:43.518 |//SIP/SIPTcp/wait_SdlReadRsp: Incoming SIP TCP message from 172.22.21.114 on port 35180 index 1946167 with 1173 bytes:
[25635906,NET]
INVITE sip:71887069170@172.22.46.40:5071 SIP/2.0
Via: SIP/2.0/TCP 172.22.21.114:5071;branch=z9hG4bK6e8d830bfb6ab
From: <sip:03371444693@172.22.21.114>;tag=736060~59bc1f5c-32f4-4c4f-86b6-b643dfff01e2-34135187
To: <sip:71887069170@172.22.46.40>
Date: Wed, 23 Aug 2017 15:00:43 GMT
Call-ID: d4886500-99d1989b-2414e-721516ac@172.22.21.114
Supported: timer,resource-priority,replaces
Min-SE: 500
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.22.21.114:5071>;method="NOTIFY;Event=telephone-event;Duration=500"
Cisco-Guid: 3565708544-0000065536-0000147786-1913984684
Session-Expires: 1800
P-Asserted-Identity: <sip:03371444693@172.22.21.114>
Remote-Party-ID: <sip:03371444693@172.22.21.114>;party=calling;screen=yes;privacy=off
Contact: <sip:03371444693@172.22.21.114:5071;transport=tcp>
Max-Forwards: 70
Content-Type: application/qsig
Content-Disposition: signal;handling=optional
Content-Length: 47

++++++
100 Trying Sent to leg 1

++++++
Outgoing Invite to 172.25.35.98 on 2nd Call leg

17:00:43.522 |//SIP/SIPTcp/wait_SdlSPISignal: Outgoing SIP TCP message to 172.25.35.98 on port 5060 index 1949944
[25635908,NET]
INVITE sip:7069170@172.25.35.98:5060 SIP/2.0
Via: SIP/2.0/TCP 172.22.46.40:5060;branch=z9hG4bK54183b160dfdff
From: <sip:03371444693@172.22.46.40>;tag=9003104~94547710-8958-4cd1-96fa-8d6cf3b3c405-59215138
To: <sip:7069170@172.25.35.98>
Date: Wed, 23 Aug 2017 15:00:43 GMT
Call-ID: d4886500-99d1989b-3b85b1-282e16ac@172.22.46.40
Supported: timer,resource-priority,replaces
Min-SE: 500
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.22.46.40:5060>;method="NOTIFY;Event=telephone-event;Duration=500"
Cisco-Guid: 3565708544-0000065536-0000332729-0674109100
Session-Expires: 1800
P-Asserted-Identity: <sip:03371444693@172.22.46.40>
Remote-Party-ID: <sip:03371444693@172.22.46.40>;party=calling;screen=yes;privacy=off
Contact: <sip:03371444693@172.22.46.40:5060;transport=tcp>
Max-Forwards: 69
Content-Length: 0

++++++
Incoming 100 Tryng from Leg 2

++++++
Outgoing PriAlertingMsg

17:00:43.987 |Out Message -- PriAlertingMsg -- Protocol= PriQsigProtocol|*^*^*
17:00:43.987 |Ie - Q931FacilityIe IEData= 1C 13 9F AA 06 80 01 00 82 01 00 A1 08 02 01 01 02 01 01 84 00 |*^*^*
17:00:43.987 |MMan_Id= 0. (iep= 0 dsl= 0 sapi= 0 ces= 0 IpAddr=0 IpPort=0)|*^*^*
17:00:43.987 |IsdnMsgData2= 08 02 99 D5 01 1C 13 9F AA 06 80 01 00 82 01 00 A1 08 02 01 01 02 01 01 84 00 |*^*^*

++++++
Now CUCM receives 183 session Progress message from 172.25.35.98 with SDP and is negotiating G729,PCMA and PCMU

17:00:43.985 |//SIP/SIPTcp/wait_SdlReadRsp: Incoming SIP TCP message from 172.25.35.98 on port 5060 index 1949944 with 882 bytes:
[25635910,NET]
SIP/2.0 183 Session Progress
Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, OPTIONS, REFER, REGISTER, INFO, UPDATE, PRACK
Call-ID: d4886500-99d1989b-3b85b1-282e16ac@172.22.46.40
Contact: <sip:7069170@172.25.35.98:5060;transport=TCP>
Content-Length: 315
Content-Type: application/sdp
CSeq: 101 INVITE
From: <sip:03371444693@172.22.46.40>;tag=9003104~94547710-8958-4cd1-96fa-8d6cf3b3c405-59215138
Server: SONUS SBC1000 5.0.1v399 Sonus SBC
To: <sip:7069170@172.25.35.98>;sgid=3;tag=ac192362-66513
Via: SIP/2.0/TCP 172.22.46.40:5060;branch=z9hG4bK54183b160dfdff

v=0
o=SBC 44164 1001 IN IP4 172.25.35.98
s=VoipCall
c=IN IP4 172.25.35.98
t=0 0
m=audio 16730 RTP/AVP 18 8 0 101 13
c=IN IP4 172.25.35.98
a=rtpmap:18 G729/8000/1
a=rtpmap:8 PCMA/8000/1
a=rtpmap:0 PCMU/8000/1
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=rtpmap:13 CN/8000
a=ptime:20
a=sendrecv

++++++
Now CUCM sends 180 message to the 1st call leg

17:00:43.987 |//SIP/SIPTcp/wait_SdlSPISignal: Outgoing SIP TCP message to 172.22.21.114 on port 35180 index 1946167
[25635911,NET]
SIP/2.0 180 Ringing
Via: SIP/2.0/TCP 172.22.21.114:5071;branch=z9hG4bK6e8d830bfb6ab
From: <sip:03371444693@172.22.21.114>;tag=736060~59bc1f5c-32f4-4c4f-86b6-b643dfff01e2-34135187
To: <sip:71887069170@172.22.46.40>;tag=9003103~94547710-8958-4cd1-96fa-8d6cf3b3c405-59215137
Date: Wed, 23 Aug 2017 15:00:43 GMT
Call-ID: d4886500-99d1989b-2414e-721516ac@172.22.21.114
CSeq: 101 INVITE
Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY
Allow-Events: presence
Supported: X-cisco-srtp-fallback
Supported: Geolocation
P-Asserted-Identity: <sip:7069170@172.22.46.40>
Remote-Party-ID: <sip:7069170@172.22.46.40>;party=called;screen=yes;privacy=off
Contact: <sip:71887069170@172.22.46.40:5071;transport=tcp>
Content-Type: application/qsig
Content-Disposition: signal;handling=optional
Content-Length: 28

++++++
Now 180 Ringing is received on call leg 2

17:00:44.290 |//SIP/SIPTcp/wait_SdlReadRsp: Incoming SIP TCP message from 172.25.35.98 on port 5060 index 1949944 with 525 bytes:
[25635912,NET]
SIP/2.0 180 Ringing
Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, OPTIONS, REFER, REGISTER, INFO, UPDATE, PRACK
Call-ID: d4886500-99d1989b-3b85b1-282e16ac@172.22.46.40
Contact: <sip:7069170@172.25.35.98:5060;transport=TCP>
Content-Length: 0
CSeq: 101 INVITE
From: <sip:03371444693@172.22.46.40>;tag=9003104~94547710-8958-4cd1-96fa-8d6cf3b3c405-59215138
Server: SONUS SBC1000 5.0.1v399 Sonus SBC
To: <sip:7069170@172.25.35.98>;sgid=3;tag=ac192362-66513
Via: SIP/2.0/TCP 172.22.46.40:5060;branch=z9hG4bK54183b160dfdff

++++++
Now 200 Ok is received with SDP on call leg 2 after 180 RInging as above

17:00:44.531 |//SIP/SIPTcp/wait_SdlReadRsp: Incoming SIP TCP message from 172.25.35.98 on port 5060 index 1949944 with 903 bytes:
[25635913,NET]
SIP/2.0 200 OK
Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, OPTIONS, REFER, REGISTER, INFO, UPDATE, PRACK
Call-ID: d4886500-99d1989b-3b85b1-282e16ac@172.22.46.40
Contact: <sip:7069170@172.25.35.98:5060;transport=TCP>
Content-Length: 315
Content-Type: application/sdp
CSeq: 101 INVITE
From: <sip:03371444693@172.22.46.40>;tag=9003104~94547710-8958-4cd1-96fa-8d6cf3b3c405-59215138
Server: SONUS SBC1000 5.0.1v399 Sonus SBC
Supported: replaces,update,100rel
To: <sip:7069170@172.25.35.98>;sgid=3;tag=ac192362-66513
Via: SIP/2.0/TCP 172.22.46.40:5060;branch=z9hG4bK54183b160dfdff

v=0
o=SBC 44164 1003 IN IP4 172.25.35.98
s=VoipCall
c=IN IP4 172.25.35.98
t=0 0
m=audio 16730 RTP/AVP 18 8 0 101 13
c=IN IP4 172.25.35.98
a=rtpmap:18 G729/8000/1
a=rtpmap:8 PCMA/8000/1
a=rtpmap:0 PCMU/8000/1
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=rtpmap:13 CN/8000
a=ptime:20
a=sendrecv

++++++
PriConnectMsg sent by CUCM

17:00:44.534 |Out Message -- PriConnectMsg -- Protocol= PriQsigProtocol|*^*^*
17:00:44.534 |Ie - Q931FacilityIe IEData= 1C 13 9F AA 06 80 01 00 82 01 00 A1 08 02 01 02 02 01 02 84 00 |*^*^*
17:00:44.534 |Ie - Q931ConnectedNumIe IEData= 4C 09 00 81 37 30 36 39 31 37 30 |*^*^*
17:00:44.534 |MMan_Id= 0. (iep= 0 dsl= 0 sapi= 0 ces= 0 IpAddr=0 IpPort=0)|*^*^*
17:00:44.534 |IsdnMsgData2= 08 02 99 D5 07 1C 13 9F AA 06 80 01 00 82 01 00 A1 08 02 01 02 02 01 02 84 00 4C 09 00 81 37 30 36 39 31 37 30 |*^*^*

++++++
200 ok is sent on leg 1 with SDP

17:00:44.535 |//SIP/SIPTcp/wait_SdlSPISignal: Outgoing SIP TCP message to 172.22.21.114 on port 35180 index 1946167
[25635914,NET]
SIP/2.0 200 OK
Via: SIP/2.0/TCP 172.22.21.114:5071;branch=z9hG4bK6e8d830bfb6ab
From: <sip:03371444693@172.22.21.114>;tag=736060~59bc1f5c-32f4-4c4f-86b6-b643dfff01e2-34135187
To: <sip:71887069170@172.22.46.40>;tag=9003103~94547710-8958-4cd1-96fa-8d6cf3b3c405-59215137
Date: Wed, 23 Aug 2017 15:00:43 GMT
Call-ID: d4886500-99d1989b-2414e-721516ac@172.22.21.114
CSeq: 101 INVITE
Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY
Allow-Events: presence
Supported: replaces
Supported: X-cisco-srtp-fallback
Supported: Geolocation
Session-Expires: 1800;refresher=uas
Require: timer
P-Asserted-Identity: <sip:7069170@172.22.46.40>
Remote-Party-ID: <sip:7069170@172.22.46.40>;party=called;screen=yes;privacy=off
Contact: <sip:71887069170@172.22.46.40:5071;transport=tcp>
Content-Type: multipart/mixed;boundary=uniqueBoundary
Mime-Version: 1.0
Content-Length: 471

--uniqueBoundary
Content-Type: application/sdp

v=0
o=CiscoSystemsCCM-SIP 9003103 1 IN IP4 172.22.46.40
s=SIP Call
c=IN IP4 172.25.35.98
b=TIAS:8000
b=AS:8
t=0 0
m=audio 16730 RTP/AVP 18 101
a=rtpmap:18 G729/8000
a=ptime:20
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15

++++++
CUCM received PriDisconnectMsg

17:00:44.538 |In Message -- PriDisconnectMsg -- Protocol= PriQsigProtocol|*^*^*
17:00:44.538 |Ie - Q931CauseIe -- IEData= 08 02 80 90 |*^*^*
17:00:44.538 |MMan_Id= 0. (iep= 0 dsl= 0 sapi= 0 ces= 0 IpAddr=0 IpPort=0)|*^*^*
17:00:44.538 |IsdnMsgData1= 08 02 19 D5 45 08 02 80 90 |*^*^*

------>>>> Here 200 Ok Ack message should have been recieved by CUCM on leg 1 but INFO messages are received

17:00:44.538 |//SIP/SIPTcp/wait_SdlReadRsp: Incoming SIP TCP message from 172.22.21.114 on port 35180 index 1946167 with 645 bytes:
[25635915,NET]
INFO sip:71887069170@172.22.46.40:5071;transport=tcp SIP/2.0
Via: SIP/2.0/TCP 172.22.21.114:5071;branch=z9hG4bK6e8d923743735
From: <sip:03371444693@172.22.21.114>;tag=736060~59bc1f5c-32f4-4c4f-86b6-b643dfff01e2-34135187
To: <sip:71887069170@172.22.46.40>;tag=9003103~94547710-8958-4cd1-96fa-8d6cf3b3c405-59215137
Date: Wed, 23 Aug 2017 15:00:43 GMT
Call-ID: d4886500-99d1989b-2414e-721516ac@172.22.21.114
User-Agent: Cisco-CUCM8.6
Max-Forwards: 70
CSeq: 102 INFO
Contact: <sip:03371444693@172.22.21.114:5071;transport=tcp>
Content-Type: application/qsig
Content-Disposition: signal;handling=optional
Content-Length: 11

Note :- This info message is received due to mid call signalling to carry QSIG information here
++++++
Content-Type: application/qsig
Content-Disposition: signal;handling=optional
Content-Length: 11

Below is the media disconnect request
++++++
17:00:44.538 |ARBTRY-ConnectionManager- wait_AuDisconnectRequest CI(59215137,59215138),disconnectType(1), IFHandling(0,0)|3,100,63,1.12809573^172.22.21.114^*

Conclusion :-
IOS is diconnecting the call that is why we can see cause code as 16 [Normal Call disconnect]

Can you share the show run from the gateway and advise what exactly the call flow is like. As if now it is evident that QSIG is being used in the call set up. You can try below things as per
set up that you have

-->>To have IOS decode QSIG messages
voice service voip
qsig decode

-->>For Transparent Tunneling of QSIG and Q.931 over SIP/H.323:
voice service voip
signaling forward unconditional

-->>For CME with QSIG PBX:
voice service voip
qsig decode

voice service pots
supplementary-service qsig call-forward

HTH
Regards
Abhay

Regards
Abhay Singh Reyal
The Only Way To Do Great Work Is To Love What You Do. If You Haven’t Found It Yet, Keep Looking. Don’t Settle

massimiliano.mariani1 · ‎08-30-2017

Hello Abhay,

This is the call flow:

IP Phone -> 1st CUCM -> 2nd CUCM -> SBC -> Lync

I'll provide you sh run of the router gw involved.

Regards

Max

massimiliano.mariani1 · ‎08-30-2017

Hello Abhay,

Just some more details in order to focus the investigation:

- same issue is present for internal calls also where voice-gateway is not involved

- qsig decode protocol feature is active already between 1st CUCM and 2nd CUCM (SME)

- keep in mind that same scenaio is present when ip phone/PSTN calls single Lync User and it works properly.

- Problem is present from ip phone/PSTN towards Lync Responde Group Service only, and after Lync Service restart first call it works always, but second call fails always and failing is still present till another Lync Response Group service restart (I enclose you OK call trace, log is the same sent already)

My doubt is that probably CUCM needs MTP HW resources and not SW only, what do you think?

Regards

Max

Disconnect Calls from CUCM 8.6 to Lync - MRM::waiting_AllocateMtpResourceErr - ERROR - no resources are available