H323-CUBE-SIP possible in GNS3 ? - Page 2

Yan Tian · ‎12-07-2013

Hello all,

I have set up a voice lab with below topology

SCCP Extension (2001/ Mask: +14082022001)----CUCM 7.0---H323-----CUBE-----SIP------CUCME---SCCP Extension (6001/Mask: +861062286001)

However, when 2001 call 6001, 6001 only rings for 1 time, and 2001 hears busy tone.

debug voice ccapi inout on CUBE, call disconnect with cause value=47, no resource available.

debug ccsip message on CUBE, CUBE sends SIP CANCEL message after it receives SIP 180 Ringing without SDP.

Obviously, call disconnects because CUBE has no DSP to generate local ringback tone.

Even though we enable CUCME to send SIP 183 Session Progress, CUCME also needs DSP to generate early-media.

So, I conclude that GNS3 is not able to emulate H323-CUBE-SIP scenario due to inablility to emulate DSP.

Just want to double confirm with you experts here?

Thanks in advance.

Yan Tian · ‎12-12-2013

Hey aokanlawon,

Sorry for the delay. But, I am pretty sure that I enabled Detailed Level for SDI Trace before I made the testing call and collected the trace. As you can see from attachment.

What I disabled before the testing call was SDL trace as it was too low-level. Do you want me to enable the SDL trace as well?

One reason that you did not see the detailed-level trace, I think, is that perhaps the trace log was still in the memory and still not be pushed to the log file when I collected the log file through RTMT.

Can you please further share some docs or links about how to read the SDI trace, so that I can do the first check on my end and make sure the log files I attached is what you want.

Thanks.

Ayodeji Okanlawon · ‎12-12-2013

As you can see you have not selected some fields on your trace configuration..eg phone device trace..I suggest you tick all the box, this is what I usually set my trace fields to..

Secondly when you collect the logs, you need to search in the traces that you have the calling and called number in the log files..

Lastly reading cucm traces require experience and detail understanding of the call flow and cucm processes. You will need to study the following book, if you really want to know how to read cucm traces.. This is what I used and still use to troubleshoot CUCM

http://www.amazon.com/Troubleshooting-Cisco-Telephony-Paul-Giralt/dp/1587050757

Please rate all useful posts

"opportunity is a haughty goddess who waste no time with those who are unprepared"

Please rate all useful posts

Yan Tian · ‎12-12-2013

Hello aokanlawon,

Thanks for your sharing, please see attachment for my 2nd SDI trace with all boxes ticked.

Ayodeji Okanlawon · ‎12-12-2013

Tian,

These logs do not contain the traces for this call..How many cucm server do you have? I also said you should check that you can find the calling and called numbers in the logs before sending it over....Please ensure that the calling and called number is present..

Please rate all useful posts

"opportunity is a haughty goddess who waste no time with those who are unprepared"

Please rate all useful posts

Yan Tian · ‎12-13-2013

Hey aokanlawon,

Sorry for the delay.

I have only 1 server in my CUCM cluster. I think the related call traces are inside ccm00000021.txt, as I found below:

CCM|//SIP/SIPTcp/wait_SdlReadRsp: Incoming SIP TCP message from 142.1.64.254 on port 5060 index 1 with 962 bytes:

SIP/2.0 200 OK

Via: SIP/2.0/TCP 142.100.64.11:5060;branch=z9hG4bK07aed2d97

From: "HQ Phone 1" <>;tag=0140a88e-20ea-4ea4-98ef-fc4a3f05c677-33238630

To: <900861062286001>;tag=226B5C-1238

Date: Fri, 01 Mar 2002 00:37:35 GMT

.............................................

CLID::StandAloneCluster><:142.100.64.11><:1><:142.1.64.254><:><:SPECIAL><:8000>

03/01/2002 00:37:48.752 CCM|MRM::getXcodeDeviceGivenMrgl GETTING XCODE FROM DEFAULT LIST|<:STANDALONECLUSTER><:142.100.64.11><:1><:142.1.64.254><:><:SPECIAL><:8000>

03/01/2002 00:37:48.752 CCM|MediaResourceManager::sendAllocationResourceErr - ERROR - no transcoder device configured|<:STANDALONECLUSTER><:142.100.64.11><:1><:142.1.64.254><:><:ERROR><:8000>

03/01/2002 00:37:48.752 CCM|MtpNoMoreResourcesAvailable - No more MTP resources available. App ID:Cisco CallManager Cluster ID:StandAloneCluster Node ID:CUCM701-Pub

...................................................................................................................

<:STANDALONECLUSTER><:142.100.64.11><:1><:142.1.64.254><:><:SIGNIFICANT><:0800>

03/01/2002 00:37:48.754 CCM|MediaManager(1)::disconnOnResourceAllocationFailure, ERROR disconnOnResourceAllocationFailure - fails to allocate MTP/XCoder,connCount=3|

.................................................................

CCM|//SIP/SIPTcp/wait_SdlSPISignal: received a spi signal ...|<:STANDALONECLUSTER><:142.100.64.11><:0><:><:><:DETAILED><:20000>

03/01/2002 00:37:48.766 CCM|//SIP/SIPTcp/wait_SdlSPISignal: Outgoing SIP TCP message to 142.100.64.254 on port 5060 index 2

ACK sip:900861062286001@142.100.64.254:5060;transport=tcp SIP/2.0

Date: Fri, 01 Mar 2002 00:37:35 GMT

From: "HQ Phone 1" <>;tag=0140a88e-20ea-4ea4-98ef-fc4a3f05c677-33238630

Allow-Events: presence, kpml

Content-Length: 0

To: <900861062286001>;tag=226B5C-1238

Call-ID: 84e43700-c7e1cd4f-1-b40648e@142.100.64.11

Via: SIP/2.0/TCP 142.100.64.11:5060;branch=z9hG4bK16215b5e1

CSeq: 101 ACK

Max-Forwards: 70

.....................................................................

<:STANDALONECLUSTER><:142.100.64.11><:1><:142.1.64.254><:><:SPECIAL><:8000>

03/01/2002 00:37:48.786 CCM|MRM::waiting_DeallocateMtpResourceReq- ERROR Deallocate received for an unknown Call Identifier Ci = 33238632|

......................................................................

<:STANDALONECLUSTER><:142.100.64.11><:1><:142.1.64.254><:><:DETAILED><:20000>

03/01/2002 00:37:48.790 CCM|//SIP/SIPTcp/wait_SdlSPISignal: Outgoing SIP TCP message to 142.100.64.254 on port 5060 index 2

BYE sip:900861062286001@142.100.64.254:5060;transport=tcp SIP/2.0

Reason: Q.850;cause=47

Date: Fri, 01 Mar 2002 00:37:35 GMT

From: "HQ Phone 1" <>;tag=0140a88e-20ea-4ea4-98ef-fc4a3f05c677-33238630

P-Asserted-Identity: "HQ Phone 1" <>

Content-Length: 0

User-Agent: Cisco-CUCM7.0

To: <900861062286001>;tag=226B5C-1238

Call-ID: 84e43700-c7e1cd4f-1-b40648e@142.100.64.11

Via: SIP/2.0/TCP 142.100.64.11:5060;branch=z9hG4bK216bb1dcc

CSeq: 102 BYE

Max-Forwards: 70

I put IP phone 2001 and SIP GW in the same Region, and put MTP in the Default Region, set G.711 between those 2 regions. I am wondering why Xcoding Resouce is invoked?

Thanks in advance.

Ayodeji Okanlawon · ‎12-14-2013

Tian,

You are right..I also looked closer and I saw this

03/01/2002 00:37:48.749 CCM|RegionsServer::MatchCapabilities -- kbps=64, capACount=5, capBCount=6|<:STANDALONECLUSTER><:142.100.64.11><:DETAILED><:0800>
03/01/2002 00:37:48.749 CCM|MediaManager(1)::preCheckCapabilities, kbps(64),capA[2][4], capB[5][86]|<CLID::StandAloneCluster><:142.100.64.11><:1><:142.1.64.254><:><:DETAILED><:0800>
03/01/2002 00:37:48.749 CCM|MediaManager(1)::prepareConnectionsWithOneSavedConnectionWithParty2, savedConnRes=MTP,xcoderReqd=1 xcodingSide=1

Even though the capabilities showed that G711 is set between the two regions, CUCM still wants to allocate a xcoder..That doesnt look right..

Try this, put the MTP is the same region as the phone 1.e Reg-HQ, and test again...

Please rate all useful posts

"opportunity is a haughty goddess who waste no time with those who are unprepared"

Please rate all useful posts

Yan Tian · ‎12-14-2013

Hey aokanlawon,

Thanks for your reply.

I have tried to put IP phone (2001), SIP GW, MTP in the same device pool, however, problem still persists.

I am really running out of ideas for further troubleshooting. I suspect we are running into a bug or defect ??

amansin74 · ‎12-14-2013

Hi Tian,

Which version of ios are you running?

I would like you to try the following:

voice service voip

no ip address trusted authenticate

Give the above commands on all your Gateways ( H323, CUBE & CME)

I have had call disconnect issues when i used to make long chain of Voip Call legs with disconnect cause suggesting nothing.

If it works for you.. you know where to look.

use following command to find out exactly where you need to add IP in the trust list.

show ip address trusted list

My assumption (based on my lab experience) - You will need to add H323 gateway IP address in CME and CME IP address in H323 gateway.

Command to do this:

voice service voip
 ip address trusted list
  ipv4 203.0.113.100 255.255.255.255
  ipv4 192.0.2.0 255.255.255.0

For your reference:

http://www.cisco.com/c/en/us/support/docs/voice/call-routing-dial-plans/112083-tollfraud-ios.html

Let me know if it helped.

Regards,

Aman

--

“If you have knowledge, let others light their candles in it.”

Ayodeji Okanlawon · ‎12-14-2013

Aman,

This has nothing to do with ip address authentication...First of all he is running IOS 12.4..sencond cause code for ip address authentication is "21" not "47"..Thirdly there te ip address of cucm is defined in the dial-peer on the gateway

Please rate all useful posts

"opportunity is a haughty goddess who waste no time with those who are unprepared"

Please rate all useful posts

Ayodeji Okanlawon · ‎12-14-2013

Tian,

I agree, looks like this is a defect....Can we try another thing..Lets use G711alaw as the MTP originating codec, reset the sip trunk...Then configure voice class codec on your inbound dial-peers as follows..

voice class codec 1

codec preference 1 g711ulaw

codec preference 2 g711alaw

codec preference 3 g729r8

Ensure you configure this also on the inbound dial-peer of ccme

Please rate all useful posts

"opportunity is a haughty goddess who waste no time with those who are unprepared"

Please rate all useful posts

Yan Tian · ‎12-15-2013

Hey aokanlawon & amansin,

Thank you all for your reply. I have tried the voice class command, and unfortunately nothing changed, call disconnect with the same cause code Reason: Q.850;cause=47,

I will try another CUCM version in my lab to see if it makes a difference, and update here.

Yan Tian · ‎12-27-2013

Hey aokanlawon,

Just let you updated with my latest findings.

All my previous testing were conducted in below Scenario;

SCCP Extension (2001/Directly run on my Laptop)----CUCM 7.0(VMware Guest OS)---H323-----CUBE(GNS3 Router)-----SIP------CUCME(GNS3 Router)---SCCP Extension (6001/ VMware Guest OS-Win XP)

That is why you can see in the trace that the IP address of SCCP Extension 2001 is 142.100.64.12

Now, When I run SCCP Extension (2001) on a newly-created VMware Guest OS as well, like below;

SCCP Extension (2001/VMware Guest OS #1-Win XP)----CUCM 7.0(VMware Guest OS)---H323-----CUBE(GNS3 Router)-----SIP------CUCME(GNS3 Router)---SCCP Extension (6001/ VMware Guest OS #2-Win XP)

And I can see the IP address of SCCP Extension 2001 is 142.102.64.101. To my surprise, the call is setup normally, RTP packets exchanged and can be normally disconnected when one party hangs up. However I can still hear 2 beeps when the the called party pick up the call, I think that indicates the failure of Xcode resource allocatoin.

I spent couple of days learning SDI trace viewing, and further looked into the trace of the failed call and encounter below confusions. Note that all below traces happened before CUCM sent SIP INVITE message on SIP Trunk.

Firstly, Call Initialized by Extension 2001 and creates 1st call leg (between phone & CUCM) with Reference=33238629

CCM|StationInit: (0000001) EnblocCall calledParty=900861062286001.|

CCM|StationD: (0000001) StopTone.|

CCM|StationD: (0000001) SelectSoftKeys instance=1 reference=33238629 softKeySetIndex=6 validKeyMask=ffffffff.|

Then, CUCM perform the call routing and creates 2nd call leg (between CUCM & SIP GW) with Reference=33238630

CCM|RouteListControl::idle_CcSetupReq - RouteList(RL-LRG), numberSetup=0 numberMember=0 vmEnabled=0|

CCM|RouteListControl::idle_CcSetupReq - RouteList(RL-LRG), RouteListCdrc::create CI = 33238630 BRANCH = 0|

CCM|SMDMSharedData::findLocalDevice - Name=HQ-SIP-Trunk Key=354e2723-eea8-7625-671f-4c6fa0534990 isActvie=1 Pid=(1,52,1) found|

CUCM Begins to compare DTMF capabilities between SIP Trunk (mLocalDtmfCaps) and SIP GW (mEndppointsDtmfCaps).

CCM|SIP DTMF Info: mLocalDtmfCaps...UNSOL=1, KPML=1, Inband=1(0) mEndppointsDtmfCaps...UNSOL=1, KPML=0, Inband=0(0) mDefaultTelephonyEvent=101, mDtmfPreference=1, mMtpAllocated=0|

Even though Both SIP Trunk & SIP GW support UNSOL, MTP resource is still required, I guess this is because I manually enabled "MTP Required" on SIP Trunk. Again, new call leg with Reference=33238631 is created between MTP and CUCM.

CCM|MediaResourceManager::waiting_MrmAllocateMtpResourceReq CI=33238631, Count=1|

As MTP is gonna be the transit station for the media flow between Extension 2001 and SIP GW, CUCM begins to do the capability matching between Extension 2001 [A(6,RG-HQ)] and MTP, as well as between MTP and SIP GW [B(1,RG-HQ)].

CCM|MediaTerminationPointControl(1)::waiting_AllocateMtpResourceReq - (capCount,region),A(6,RG-HQ),B(1,RG-HQ), reqDevCap=0x9, supDevCap=0x9, passthru=0, resourceCount=1|

CCM|MediaTerminationPointControl(1)::getResourcesAllocated -- DeviceName=MTP_1 Ci=33238631 ResourceCount=1|

CCM|MediaTerminationPointControl(1)::getResourcesAllocated -- Logging RegionA=RG-HQ Caps and MTP/XCoder Region=RG-Default Caps|

CCM|MediaTerminationPointControl(1)::logCapabilitiesinTrace -- MTP/XCoder Device Caps = 25 4 2 257 259 |

CCM|MediaTerminationPointControl(1)::logCapabilitiesinTrace -- Device Caps = 86 15 16 11 12 257 |

CCM|RegionsServer::MatchCapabilities -- kbps=64, capACount=6, capBCount=5|

CCM|MediaTerminationPointControl(1)::getResourcesAllocated -- Logging RegionB=RG-HQ Caps and MTP/XCoder Region=RG-Default Caps|

CCM|MediaTerminationPointControl(1)::logCapabilitiesinTrace -- MTP/XCoder Device Caps = 25 4 2 257 259 |

CCM|MediaTerminationPointControl(1)::logCapabilitiesinTrace -- Device Caps = 4 |

CCM|RegionsServer::MatchCapabilities -- kbps=64, capACount=1, capBCount=5|

CCM|MediaTerminationPointControl(1)::getResourcesAllocated -- No matching caps for either side A or side B, MTP not allocated|

CCM|MediaTerminationPointControl(1)::getResourcesAllocated -- match1=0 match2=1|

CCM|MediaTerminationPointControl(1)::getResourcesAllocated -- allocateErrBitset=0x20|

CCM|MediaTerminationPointControl(1)::SendMTPResourceErrToSender - ERROR AllocateMtpResourceReq failed -- Ci=33238631, errBitset=0x24|

CCM|MediaResourceCdpc(1)::resource_rsvp_AllocateMtpResourceErr Device=MTP_1 deviceCapIntersec=9|

CCM|MediaResourceCdpc(1)::adjustDeviceTblMTP - mCepn=f5b2456a-4066-4210-a92b-e1e3c1b51ac6, allocateErrBitset=0x24, devCapIntersect=0x9, resourceCount=1|

CCM|MediaResourceCdpc(1)::adjustDeviceTblMTP - Codec Mismatch|

CCM|MediaResourceCdpc(1)::removeDevicePidTableEntry - cepn=f5b2456a-4066-4210-a92b-e1e3c1b51ac6 deviceName=MTP_1 deviceTblSize=0|

CCM|MediaResourceCdpc(1)::mtpErrorResponseToManager - CI=33238631|

CCM|MRM::waiting_AllocateMtpResourceErr - Deallocate not received for this ci = 33238631. Process normally|

CCM|MtpNoMoreResourcesAvailable - No more MTP resources available. App ID:Cisco CallManager Cluster ID:StandAloneCluster Node ID:CUCM701-Pub|

CCM|MRM::waiting_AllocateMtpResourceErr - ERROR - no resources are available -- ci = 33238631

=========Query======================================================

MTP/XCoder Device Caps = 25 4 2 257 259, Device Caps = 86 15 16 11 12 257,

What do those numbers stand for? any reference for this ?

match1=0 match2=1, Seems that CUCM does not find codec in common between MTP & Phone (match1=0), and only 1 codec in common between MTP and SIP GW (match2=1), that is why CUCM requires transcoding which actually does not exist, thus call fails.

Then I further review the subsequent traces which indicates that CUCM invokes the MTP again with another Reference=33238632, Why CUCM invokes MTP again??

========Query Ends=============================================

CCM|MediaResourceManager::waiting_MrmAllocateMtpResourceReq CI=33238632, Count=1|

CCM|MediaResourceCdpc(2)::sendMtpAllocateRequestToDevice MtpResource=MTP_1 Cepn=f5b2456a-4066-4210-a92b-e1e3c1b51ac6|

CCM|MediaTerminationPointControl(1)::waiting_AllocateMtpResourceReq - (capCount,region),A(0,RG-HQ),B(1,RG-HQ), reqDevCap=0x9, supDevCap=0x9, passthru=0, resourceCount=1|

CCM|MediaTerminationPointControl(1)::getResourcesAllocated -- DeviceName=MTP_1 Ci=33238632 ResourceCount=1|

CCM|MediaTerminationPointControl(1)::getResourcesAllocated -- Logging RegionA=RG-HQ Caps and MTP/XCoder Region=RG-Default Caps|

CCM|MediaTerminationPointControl(1)::logCapabilitiesinTrace -- MTP/XCoder Device Caps = 25 4 2 257 259 |

CCM|MediaTerminationPointControl(1)::logCapabilitiesinTrace -- Device Caps = |

CCM|MediaTerminationPointControl(1)::getResourcesAllocated -- Logging RegionB=RG-HQ Caps and MTP/XCoder Region=RG-Default Caps|

CCM|MediaTerminationPointControl(1)::logCapabilitiesinTrace -- MTP/XCoder Device Caps = 25 4 2 257 259 |

CCM|MediaTerminationPointControl(1)::logCapabilitiesinTrace -- Device Caps = 4 |

CCM|RegionsServer::MatchCapabilities -- kbps=64, capACount=1, capBCount=5|

CCM|MediaTerminationPointControl(1)::getResourcesAllocated -- match1=1 match2=1|

CCM|MediaTerminationPointControl(1)::getResourcesAllocated -- DeviceName=MTP_1 Ci=33238632 ResourceAllocated=1|

CCM|MediaTerminationPointControl(1)::getResourcesAllocated -- allocateErrBitset=0x0|

CCM|MediaTerminationPointControl(1)::handleMtpDeviceFound|

CCM|MediaTerminationPointControl(1)::logResourceStatusinTrace -- Device Name=MTP_1 ResourceAvailable=24 ResourceUsed=0|

CCM|MediaTerminationPointControl(1)::handleMtpDeviceFound ConversationId=16782217 CI=33238632 Allocated resource=1 Device Capability = 9|

CCM|MediaTerminationPointControl(1)::incActiveCounter - Count=1|

CCM|MediaTerminationPointControl(1)::decAvailableCounter - Count=1|

CCM|MediaTerminationPointControl(1)::logResourceStatusinTrace -- Device Name=MTP_1 ResourceAvailable=23 ResourceUsed=1|

CCM|MediaResourceCdpc(2)::resource_rsvp_AllocateMtpResourceRes CI=33238632, DeviceCapability=9, Count=1|

CCM|MediaResourceCdpc(2)::getMrglGivenDeviceName - DeviceName=MTP_1 MRGLPkid=b48eb759-e446-37db-1b50-503d26c6b118|

CCM|MediaResourceManager::waiting_MrmAllocateMtpResourceRes - CI=33238632 deviceName=MTP_1 deviceCap=9 count=1|

CCM|MRM::updateMtpCounter MTP_1|

CCM|MRM::MRM::updateMtpCounter MRL allocateCounter=1|

CCM|MRM::updateXcodeCounter MTP_1|

CCM|setLocalDtmfCaps: supportedDTMFMethod=2, mWantDtmfReception=1, mPeersWantDtmfReceptionFlag=0, mDtmfPreference=1|

CCM|SIP DTMF Info: mLocalDtmfCaps...UNSOL=0, KPML=1, Inband=1(101) mEndppointsDtmfCaps...UNSOL=1, KPML=0, Inband=0(0) mDefaultTelephonyEvent=101, mDtmfPreference=1, mMtpAllocated=1|

CCM|MediaResourceCdpc(2)::shutting_down_MrmChildStopConf|

CCM|MediaTerminationPointControl(1)::star_MediaExchangeAgenaOpenLogicalChannel - PartyId = 16777217|

CCM|MediaTerminationPointControl(1)::fillAudioPartyIDtoMediaPidTable - PartyId = 16777217, OLCRecd=1, StartTlkRecd=0|

CCM|MediaTerminationPointControl(1)::star_StationOutputOpenReceiveChannel - TCPPid = [1.100.9.3] myIP: 0xb40648e (142.100.64.11) ConferenceID: 16782217, MediaPartyId: 16777217, msecPacketSize: 20 compressionType: 4|

CCM|CallManagerServiceAlarm: DeviceName = b48eb759-e446-37db-1b50-503d26c6b118, AlarmType = 1|

CCM|-->RISCMAccess::CallManagerServiceAlarm(...)|

CCM|createFile: fileName = Global\EXHAUSTMEDIARESCLISTTABLEMAPFILE0 _ElemTableSize =500 totalsize = 322016|

CCM|CCM Alarm: Push_back offset 1 seq 1|

CCM|<--RISCMAccess::CallManagerServiceAlarm(...)|

CCM|StationInit: (0000001) OpenReceiveChannelAck Status=0, IpAddr=IpAddr.type:0 ipAddr:0x8e64400b000000000000000000000000(142.100.64.11), Port=24576, PartyID=16777217|

CCM|//SIP/SIPCdpc(1,53,1)/ci=33238630/ccbId=2/scbId=0/getDefCcRegister: Secure

==================== Query Begins==================================================

For the 2nd MTP resource invoke,

MTP/XCoder Device Caps = 25 4 2 257 259, Device Caps = , Why device capability is empty ?

match1=1 match2=1, why match1=1 even though device capability is empty ?

==================== Query Ends ===================================================

Thanks a lot in advance.