cancel
Showing results for 
Search instead for 
Did you mean: 
cancel
5751
Views
35
Helpful
14
Replies

Check Media Resource Negotiation in CUCM logs

Nikhil.ranjan
Level 1
Level 1

Hi there,

 

Is there any document available that would tell me how the media negotiations during a call and how can I read the CUCM logs to verify.

Also how to we get to know if the calls has failed due to media resources issue by checking the cucm logs. 

3 Accepted Solutions

Accepted Solutions

Ayodeji Okanlawon
VIP Alumni
VIP Alumni

Hi Nikhil,

I know this is an old thread but I wanted to provide some inputs based on a few media resources issues I have looked at in the past

Here are a few analysis I did a whole back. This will help you in understanding CUCM media resource negotiation process

Example 1:

Wrong Transcoder was allocated, question is why...:

 

++++This trace shows the wrong region setting between Felhm and Miha cube and Xcoders. and showed why solihull is been used for xcoding++++++

To understand this trace here are a few concept to grab.

 

1. CUCM will always indicate why it needs to invoke a media resource ( xcoder or MTP)

2. CUCM always allocate a CI for each media resource allocation process. This is key in knowing what happened to the resource allocation request

3. CUCM always evaluate the region settings between xcoder and the parties that needs it. It then evaluates the codec capabilities of each party including the xcoder against the region setting

4. The higher bit rate party always invokes the xcoder.

5. You need atleast one side to be G711 to invoke a normal xcoder, otherwise you will need a universal xcoder. ( if both parties are on G722, or one side is G722 and other is G729)

 

6. Finally you need to know the most popular codec caps values

g729abr8------------16

g729ar8-------------12

g729r8--------------11

g711alaw------------2

g711ulaw-------------4

g722-64k-------------6

 

Now lets apply these in the example below:

Example 1:

++MTP is needed because DTMF mismatch..SIPleg=rtp-nte, gatekepeer leg=OOB(h245-alpha)+++

But MTP allocation failed. Why?

 

++ CUCM tells us why its allocation MTP ++


20:41:48.467 |DET-MediaManager-(145799)::AllocateXcoderandMTPWithZeroSavedConnection|32,100,63,1.170805^10.105.40.200^*
20:41:48.467 |DET-MediaManager-(145799)::isMTPNeededForMismatchOrConfig, MTPNeededDueToDTMFCapMismatch(2833/OOB) mtpinsertionReason=1 dtmfMTPSide=1|32,100,63,1.170805^10.105.40.200^*

:sendMTPXcoderAllocationRequest, (CapCount,Region),SideA:(24,FELHM_MILHA_REG01), SideB:(24,SYS_GK_REG01), supressMatchCap=1,MTPNeededForDTMF=1|32,100,63,1.170805^10.105.40.200^*

 

+++ CUCM evaluates Regions and Capabilities between Chosen xcoder  ( I have ommited some traces) ++

 

++ Part 1, CUCM evaluates the region between side A and the xcoder ++
0:41:48.468 |MediaTerminationPointControl(31)::getResourcesAllocated -- Logging RegionA=FELHM_MILHA_REG01 Caps and MTP/XCoder Region=FELHM_MILHA_REG01 Caps|32,100,63,1.170805^10.105.40.200^*

 

++ Part 2 CUCM evaluates the device caps for both xcoder and the device +++
20:41:48.468 |MediaTerminationPointControl(31)::logCapabilitiesinTrace -- MTP/XCoder Device Caps = 4 2 16 11 12 257 259 261 |32,100,63,1.170805^10.105.40.200^*
20:41:48.468 |MediaTerminationPointControl(31)::logCapabilitiesinTrace -- Device capsCaps = 2 3 4 5 6 7 8 9 10 11 12 15 16 18 19 20 25 42 86 89 40 41 43 44 |32,100,63,1.170805^10.105.40.200^*

 

++ Part 3, CUCM evaluates the region setting between MTP/Xcoder and device ++
20:41:48.468 |RegionsServer::MatchCapabilities -- kbps=8, capACount=24, capBCount=8|*^*^*

 

++Part 4, CUCM repeats the same process for MTP and Side B ++


20:41:48.468 |MediaTerminationPointControl(31)::getResourcesAllocated -- Logging

RegionB=SYS_GK_REG01 Caps and MTP/XCoder Region=FELHM_MILHA_REG01 Caps|32,100,63,1.170805^10.105.40.200^*
20:41:48.468 |MediaTerminationPointControl(31)::logCapabilitiesinTrace -- MTP/XCoder Device Caps = 4 2 16 11 12 257 259 261 |32,100,63,1.170805^10.105.40.200^*
20:41:48.468 |MediaTerminationPointControl(31)::logCapabilitiesinTrace -- Device Caps = 2 3 4 5 6 7 8 9 10 11 12 15 16 18 19 20 25 42 86 89 40 41 43 44 |32,100,63,1.170805^10.105.40.200^*
20:41:48.468 |RegionsServer::MatchCapabilities -- kbps=8, capACount=24, capBCount=8|*^*^*
20:41:48.468 |MediaTerminationPointControl(31)::getResourcesAllocated -- match1=3 match2=3|32,100,63,1.170805^10.105.40.200^*

 

++ Based on the evaluation above we can see that both sides A and B are configured to so G729 to the Xcoder. ( Remember point 5 above)- One side needs to be G711 ( if this is a xcoder used as MTP).

 

++ Hence CUCM throws up an error +++


20:41:48.468 |MediaTerminationPointControl(31)::getResourcesAllocated - ERROR LBR not support on DeviceName=SYS_MILHA_TX_01 Ci=540685347|32,100,63,1.170805^10.105.40.200^

 

Here is another rule of thumb for IOS MTP allocation: The codec configured for the MTP is what will be negotiated. If a G711MTP is configured, G711 is used ( hence both devices should talk G711 to the MTP, if a G729 MTP is used, G729 is used 

 

Example 2:

++ IOS MTP Allocation failure ++

 

Part 1 ++ CUCM selects MTP device, allocates a CI +++

 

12/08/2012 04:40:42.920 CCM|MediaTerminationPointControl(41)::getResourcesAllocated -- DeviceName=MTP-NG-SOFT Ci=20934509 ResourceCount=1|<CLID::StandAloneCluster><NID::172.20.9.135><CT::1,200,15,1.6780939><IP::172.20.9.137><DEV::jtapi_637><LVL::Detailed><MASK::0080>

 

++ Part 2, CUCM evaluates CAPS and region settings +++

Based on this we can see that the IOS MTP only supports G711ulaw


12/08/2012 04:40:42.920 CCM|MediaTerminationPointControl(41)::getResourcesAllocated -- Logging RegionA=REG-CHN-SIP Caps and MTP/XCoder Region=REG-NG-CHN Caps|<CLID::StandAloneCluster><NID::172.20.9.135><CT::1,200,15,1.6780939><IP::172.20.9.137><DEV::jtapi_637><LVL::Detailed><MASK::0080>
12/08/2012 04:40:42.921 CCM|MediaTerminationPointControl(41)::logCapabilitiesinTrace -- MTP/XCoder Device Caps = 4 257 259 261 |<CLID::StandAloneCluster><NID::172.20.9.135><CT::1,200,15,1.6780939><IP::172.20.9.137><DEV::jtapi_637><LVL::Detailed><MASK::0080>
12/08/2012 04:40:42.921 CCM|MediaTerminationPointControl(41)::logCapabilitiesinTrace -- Device Caps = 4 |<CLID::StandAloneCluster><NID::172.20.9.135><CT::1,200,15,1.6780939><IP::172.20.9.137><DEV::jtapi_637><LVL::Detailed><MASK::0080>
12/08/2012 04:40:42.921 CCM|RegionsServer::MatchCapabilities -- kbps=64, capACount=1, capBCount=4|<CLID::StandAloneCluster><NID::172.20.9.135><LVL::Detailed><MASK::0800>

 

++ Part 3, Region B ++
12/08/2012 04:40:42.921 CCM|MediaTerminationPointControl(41)::getResourcesAllocated -- Logging RegionB=REG-NG-CHN Caps and MTP/XCoder Region=REG-NG-CHN Caps|<CLID::StandAloneCluster><NID::172.20.9.135><CT::1,200,15,1.6780939><IP::172.20.9.137><DEV::jtapi_637><LVL::Detailed><MASK::0080>
12/08/2012 04:40:42.921 CCM|MediaTerminationPointControl(41)::logCapabilitiesinTrace -- MTP/XCoder Device Caps = 4 257 259 261 |<CLID::StandAloneCluster><NID::172.20.9.135><CT::1,200,15,1.6780939><IP::172.20.9.137><DEV::jtapi_637><LVL::Detailed><MASK::0080>
12/08/2012 04:40:42.921 CCM|MediaTerminationPointControl(41)::logCapabilitiesinTrace -- Device Caps = 4 2 |<CLID::StandAloneCluster><NID::172.20.9.135><CT::1,200,15,1.6780939><IP::172.20.9.137><DEV::jtapi_637><LVL::Detailed><MASK::0080>
12/08/2012 04:40:42.921 CCM|RegionsServer::MatchCapabilities -- kbps=8, capACount=2, capBCount=4|<CLID::StandAloneCluster><NID::172.20.9.135><LVL::Detailed><MASK::0800>

 

++ Now we see why this failed. Because this is a G711 IOS MTP, both sides must talk G711 to the MTP. In this case once side is configured to use G729 and the other side G711, hence MTP allocation failed. Here is the error that CUCM throws


12/08/2012 04:40:42.921 CCM|MediaTerminationPointControl(41)::getResourcesAllocated -- No matching caps for either side A or side B, MTP not allocated|<CLID::StandAloneCluster><NID::172.20.9.135><CT::1,200,15,1.6780939><IP::172.20.9.137><DEV::jtapi_637><LVL::Detailed><MASK::0080>
12/08/2012 04:40:42.921 CCM|MediaTerminationPointControl(41)::getResourcesAllocated -- match1=1 match2=0|<CLID::StandAloneCluster><NID::172.20.9.135><CT::1,200,15,1.6780939><IP::172.20.9.137><DEV::jtapi_637><LVL::Detailed><MASK::0080>
12/08/2012 04:40:42.921 CCM|MediaTerminationPointControl(41)::getResourcesAllocated -- allocateErrBitset=0x40|<CLID::StandAloneCluster><NID::172.20.9.135><CT::1,200,15,1.6780939><IP::172.20.9.137><DEV::jtapi_637><LVL::Detailed><MASK::0080>
12/08/2012 04:40:42.921 CCM|MediaTerminationPointControl(41)::SendMTPResourceErrToSender - ERROR AllocateMtpResourceReq failed -- Ci=20934509, errBitset=0x44|<CLID::StandAloneCluster><NID::172.20.9.135><CT::1,200,15,1.6780939><IP::172.20.9.137><DEV::jtapi_637><LVL::Error><MASK::0080>

 

Example 3: ( Home work):)

 

++ Wrong transcoder allocated ++

 

Can you figure out why the device named NGUK012_TX_02 was allocated? and why the other transcoders failed in this trace...

 

02:13:21.250 |MediaTerminationPointControl(31)::waiting_AllocateMtpResourceReq - (capCount,region),A(2,FELHM_MILHA_REG01),B(3,FELHM_MILHA_REG01), reqDevCap=0x0, reqMandatoryCaps=0x0, supDevCap=0x129, passthru=0, resourceCount=1|32,100,230,1.194880^10.105.40.74^*
02:13:21.250 |MediaTerminationPointControl(31)::getResourcesAllocated -- DeviceName=SYS_MILHA_TX_01 Ci=477085620 ResourceCount=1|32,100,230,1.194880^10.105.40.74^*
02:13:21.250 |MediaTerminationPointControl(31)::getResourcesAllocated -- Logging RegionA=FELHM_MILHA_REG01 Caps and MTP/XCoder Region=FELHM_MILHA_REG01 Caps|32,100,230,1.194880^10.105.40.74^*
02:13:21.250 |MediaTerminationPointControl(31)::logCapabilitiesinTrace -- MTP/XCoder Device Caps = 4 2 16 11 12 257 259 261 |32,100,230,1.194880^10.105.40.74^*
02:13:21.250 |MediaTerminationPointControl(31)::logCapabilitiesinTrace -- Device Caps = 112 4 |32,100,230,1.194880^10.105.40.74^*
02:13:21.250 |RegionsServer::MatchCapabilities -- kbps=8, capACount=2, capBCount=8|*^*^*
02:13:21.250 |MediaTerminationPointControl(31)::getResourcesAllocated -- Logging RegionB=FELHM_MILHA_REG01 Caps and MTP/XCoder Region=FELHM_MILHA_REG01 Caps|32,100,230,1.194880^10.105.40.74^*
02:13:21.250 |MediaTerminationPointControl(31)::logCapabilitiesinTrace -- MTP/XCoder Device Caps = 4 2 16 11 12 257 259 261 |32,100,230,1.194880^10.105.40.74^*
02:13:21.250 |MediaTerminationPointControl(31)::logCapabilitiesinTrace -- Device Caps = 114 11 12 |32,100,230,1.194880^10.105.40.74^*
02:13:21.250 |RegionsServer::MatchCapabilities -- kbps=8, capACount=3, capBCount=8|*^*^*
02:13:21.250 |MediaTerminationPointControl(31)::getResourcesAllocated -- No matching caps for either side A or side B, MTP not allocated|32,100,230,1.194880^10.105.40.74^*
02:13:21.250 |MediaTerminationPointControl(31)::getResourcesAllocated -- match1=0 match2=2|32,100,230,1.194880^10.105.40.74^*
02:13:21.250 |MediaTerminationPointControl(31)::getResourcesAllocated -- allocateErrBitset=0x20|32,100,230,1.194880^10.105.40.74^*
02:13:21.250 |MediaTerminationPointControl(31)::SendMTPResourceErrToSender - ERROR AllocateMtpResourceReq failed -- Ci=477085620, errBitset=0x24|32,100,230,1.194880^10.105.40.74^*
02:13:21.254 |MediaTerminationPointControl(2)::waiting_AllocateMtpResourceReq - (capCount,region),A(2,FELHM_MILHA_REG01),B(3,FELHM_MILHA_REG01), reqDevCap=0x0, reqMandatoryCaps=0x0, supDevCap=0x109, passthru=0, resourceCount=1|32,100,230,1.194880^10.105.40.74^*
02:13:21.254 |MediaTerminationPointControl(2)::getResourcesAllocated -- DeviceName=NGUK012_TX_02 Ci=477085620 ResourceCount=1|32,100,230,1.194880^10.105.40.74^*
02:13:21.254 |MediaTerminationPointControl(2)::getResourcesAllocated -- Logging RegionA=FELHM_MILHA_REG01 Caps and MTP/XCoder Region=NGUK012_REG01 Caps|32,100,230,1.194880^10.105.40.74^*
02:13:21.254 |MediaTerminationPointControl(2)::logCapabilitiesinTrace -- MTP/XCoder Device Caps = 4 2 16 11 12 257 259 261 |32,100,230,1.194880^10.105.40.74^*
02:13:21.254 |MediaTerminationPointControl(2)::logCapabilitiesinTrace -- Device Caps = 112 4 |32,100,230,1.194880^10.105.40.74^*
02:13:21.254 |RegionsServer::MatchCapabilities -- kbps=64, capACount=2, capBCount=8|*^*^*
02:13:21.254 |MediaTerminationPointControl(2)::getResourcesAllocated -- Logging RegionB=FELHM_MILHA_REG01 Caps and MTP/XCoder Region=NGUK012_REG01 Caps|32,100,230,1.194880^10.105.40.74^*
02:13:21.254 |MediaTerminationPointControl(2)::logCapabilitiesinTrace -- MTP/XCoder Device Caps = 4 2 16 11 12 257 259 261 |32,100,230,1.194880^10.105.40.74^*
02:13:21.254 |MediaTerminationPointControl(2)::logCapabilitiesinTrace -- Device Caps = 114 11 12 |32,100,230,1.194880^10.105.40.74^*
02:13:21.254 |RegionsServer::MatchCapabilities -- kbps=64, capACount=3, capBCount=8|*^*^*
02:13:21.254 |MediaTerminationPointControl(2)::getResourcesAllocated -- match1=1 match2=2|32,100,230,1.194880^10.105.40.74^*
02:13:21.254 |MediaTerminationPointControl(2)::getResourcesAllocated -- DeviceName=NGUK012_TX_02 Ci=477085620 ResourceAllocated=1|32,100,230,1.194880^10.105.40.74^*
02:13:21.254 |MediaTerminationPointControl(2)::getResourcesAllocated -- allocateErrBitset=0x0|32,100,230,1.194880^10.105.40.74^*
02:13:21.254 |MediaTerminationPointControl(2)::waiting_AllocateMtpResourceReq - MTP usage (-1) >= configured throttle percent (95) of Total Resources (10). Attempt to allocate a diffferent MTP.|32,100,230,1.194880^10.105.40.74^*
02:13:21.254 |MediaTerminationPointControl(2)::incRequestsThrottledCounter Count=1|32,100,230,1.194880^10.105.40.74^*
02:13:21.254 |MediaTerminationPointControl(2)::SendMTPResourceErrToSender - ERROR AllocateMtpResourceReq failed -- Ci=477085620, errBitset=0x2|32,100,230,1.194880^10.105.40.74^*
02:13:21.257 |MediaTerminationPointControl(2)::waiting_AllocateMtpResourceReq - (capCount,region),A(2,FELHM_MILHA_REG01),B(3,FELHM_MILHA_REG01), reqDevCap=0x0, reqMandatoryCaps=0x0, supDevCap=0x109, passthru=0, resourceCount=1|32,100,230,1.194880^10.105.40.74^*
02:13:21.257 |MediaTerminationPointControl(2)::getResourcesAllocated -- DeviceName=NGUK012_TX_02 Ci=477085620 ResourceCount=1|32,100,230,1.194880^10.105.40.74^*
02:13:21.257 |MediaTerminationPointControl(2)::getResourcesAllocated -- Logging RegionA=FELHM_MILHA_REG01 Caps and MTP/XCoder Region=NGUK012_REG01 Caps|32,100,230,1.194880^10.105.40.74^*
02:13:21.257 |MediaTerminationPointControl(2)::logCapabilitiesinTrace -- MTP/XCoder Device Caps = 4 2 16 11 12 257 259 261 |32,100,230,1.194880^10.105.40.74^*
02:13:21.257 |MediaTerminationPointControl(2)::logCapabilitiesinTrace -- Device Caps = 112 4 |32,100,230,1.194880^10.105.40.74^*
02:13:21.257 |RegionsServer::MatchCapabilities -- kbps=64, capACount=2, capBCount=8|*^*^*
02:13:21.257 |MediaTerminationPointControl(2)::getResourcesAllocated -- Logging RegionB=FELHM_MILHA_REG01 Caps and MTP/XCoder Region=NGUK012_REG01 Caps|32,100,230,1.194880^10.105.40.74^*
02:13:21.257 |MediaTerminationPointControl(2)::logCapabilitiesinTrace -- MTP/XCoder Device Caps = 4 2 16 11 12 257 259 261 |32,100,230,1.194880^10.105.40.74^*
02:13:21.257 |MediaTerminationPointControl(2)::logCapabilitiesinTrace -- Device Caps = 114 11 12 |32,100,230,1.194880^10.105.40.74^*
02:13:21.257 |RegionsServer::MatchCapabilities -- kbps=64, capACount=3, capBCount=8|*^*^*
02:13:21.257 |MediaTerminationPointControl(2)::getResourcesAllocated -- match1=1 match2=2|32,100,230,1.194880^10.105.40.74^*
02:13:21.257 |MediaTerminationPointControl(2)::getResourcesAllocated -- DeviceName=NGUK012_TX_02 Ci=477085620 ResourceAllocated=1|32,100,230,1.194880^10.105.40.74^*
02:13:21.257 |MediaTerminationPointControl(2)::getResourcesAllocated -- allocateErrBitset=0x0|32,100,230,1.194880^10.105.40.74^*
02:13:21.257 |MediaTerminationPointControl(2)::handleMtpDeviceFound|32,100,230,1.194880^10.105.40.74^*
02:13:21.257 |MediaTerminationPointControl(2)::logResourceStatusinTrace -- Device Name=NGUK012_TX_02 ResourceAvailable=11 ResourceUsed=-1|32,100,230,1.194880^10.105.40.74^*
02:13:21.257 |MediaTerminationPointControl(2)::handleMtpDeviceFound ConversationId=536954420 CI=477085620 Allocated resource=1 Device Capability = 265|32,100,230,1.194880^10.105.40.74^*
02:13:21.257 |MediaTerminationPointControl(2)::incActiveCounter - Count=1|32,100,230,1.194880^10.105.40.74^*
02:13:21.257 |MediaTerminationPointControl(2)::decAvailableCounter - Count=1|32,100,230,1.194880^10.105.40.74^*
02:13:21.257 |MediaTerminationPointControl(2)::logResourceStatusinTrace -- Device Name=NGUK012_TX_02 ResourceAvailable=10 ResourceUsed=0|32,100,230,1.194880^10.105.40.74^*
02:13:21.261 |MediaTerminationPointControl(2) - MediaExchangeAgenaAssociateReq confId=536954420 inserted AIF(15003,0)|28,100,225,15003.1^*^

 

Please rate all useful posts

View solution in original post

Hey Maren,

 

Please feel free, its my pleasure to help

Please rate all useful posts

View solution in original post

14 Replies 14

The Media Resource Manager is the CM process responsible for allocating media resources. That trace is enabled by default as part of the Cisco CallManager Service trace.

 

To access this trace, you can use the RTMT's Trace and Alert Central to access the trace. Instructions on how to gather and download traces are in the RTMT Administration Guide.

https://www.cisco.com/c/en/us/td/docs/voice_ip_comm/cucm/service/11_5_1/rtmt/CUCM_BK_C53F5FA7_00_cisco-unified-rtmt-administration-115.html

 

You will download the RTMT application itself from your CUCM (or Unity Connection).

 

Now, that said, the trace files are unbelievably verbose and it takes an experienced engineer to read the raw trace files. So you will want to get TranslatorX (available for download at www.translatorx.org) or another trace parser to help you read the traces. Also, I encourage you to limit the time range of your trace file (like set it up for a specific 10 minute window) when you set the trace gathering up so you are not dealing with an ocean of trace information.

 

Finally, you can see maps of what to look for with media resource negotiation in your trace file by looking at the Media Resources chapter of your version's SRND. Here is one for v11:

https://www.cisco.com/c/en/us/td/docs/voice_ip_comm/cucm/srnd/collab11/collab11/media.html

 

I hope this helps. The RTMT Admin guide is good for telling you how to do things, but is not as good as telling you why you might do one thing over another. But the above should help get you started. Let us know if you have questions.

Hi Maren,

 

I have been looking to develop my skills for reading the CUCM traces. So what i was looking for is some examples from CUCM traces where it is explained how the media negotiations happen for the calls so I can refer them to check the few more traces and develop to analyze my skills in reading traces. 

The maps in the guide in the link I posted will tell you what kind of messages to look for, and how and when they are generated. Locating those lines in the raw trace file is something you have to just dig in and do. I don't know of a good resource to help out with that.

Chris,

 

That first doc is amazing! Thank you!

 

Maren

Hello Chris,

 

Excellent docs. Will surely get me started.

Thanks Maren.

Ayodeji Okanlawon
VIP Alumni
VIP Alumni

Hi Nikhil,

I know this is an old thread but I wanted to provide some inputs based on a few media resources issues I have looked at in the past

Here are a few analysis I did a whole back. This will help you in understanding CUCM media resource negotiation process

Example 1:

Wrong Transcoder was allocated, question is why...:

 

++++This trace shows the wrong region setting between Felhm and Miha cube and Xcoders. and showed why solihull is been used for xcoding++++++

To understand this trace here are a few concept to grab.

 

1. CUCM will always indicate why it needs to invoke a media resource ( xcoder or MTP)

2. CUCM always allocate a CI for each media resource allocation process. This is key in knowing what happened to the resource allocation request

3. CUCM always evaluate the region settings between xcoder and the parties that needs it. It then evaluates the codec capabilities of each party including the xcoder against the region setting

4. The higher bit rate party always invokes the xcoder.

5. You need atleast one side to be G711 to invoke a normal xcoder, otherwise you will need a universal xcoder. ( if both parties are on G722, or one side is G722 and other is G729)

 

6. Finally you need to know the most popular codec caps values

g729abr8------------16

g729ar8-------------12

g729r8--------------11

g711alaw------------2

g711ulaw-------------4

g722-64k-------------6

 

Now lets apply these in the example below:

Example 1:

++MTP is needed because DTMF mismatch..SIPleg=rtp-nte, gatekepeer leg=OOB(h245-alpha)+++

But MTP allocation failed. Why?

 

++ CUCM tells us why its allocation MTP ++


20:41:48.467 |DET-MediaManager-(145799)::AllocateXcoderandMTPWithZeroSavedConnection|32,100,63,1.170805^10.105.40.200^*
20:41:48.467 |DET-MediaManager-(145799)::isMTPNeededForMismatchOrConfig, MTPNeededDueToDTMFCapMismatch(2833/OOB) mtpinsertionReason=1 dtmfMTPSide=1|32,100,63,1.170805^10.105.40.200^*

:sendMTPXcoderAllocationRequest, (CapCount,Region),SideA:(24,FELHM_MILHA_REG01), SideB:(24,SYS_GK_REG01), supressMatchCap=1,MTPNeededForDTMF=1|32,100,63,1.170805^10.105.40.200^*

 

+++ CUCM evaluates Regions and Capabilities between Chosen xcoder  ( I have ommited some traces) ++

 

++ Part 1, CUCM evaluates the region between side A and the xcoder ++
0:41:48.468 |MediaTerminationPointControl(31)::getResourcesAllocated -- Logging RegionA=FELHM_MILHA_REG01 Caps and MTP/XCoder Region=FELHM_MILHA_REG01 Caps|32,100,63,1.170805^10.105.40.200^*

 

++ Part 2 CUCM evaluates the device caps for both xcoder and the device +++
20:41:48.468 |MediaTerminationPointControl(31)::logCapabilitiesinTrace -- MTP/XCoder Device Caps = 4 2 16 11 12 257 259 261 |32,100,63,1.170805^10.105.40.200^*
20:41:48.468 |MediaTerminationPointControl(31)::logCapabilitiesinTrace -- Device capsCaps = 2 3 4 5 6 7 8 9 10 11 12 15 16 18 19 20 25 42 86 89 40 41 43 44 |32,100,63,1.170805^10.105.40.200^*

 

++ Part 3, CUCM evaluates the region setting between MTP/Xcoder and device ++
20:41:48.468 |RegionsServer::MatchCapabilities -- kbps=8, capACount=24, capBCount=8|*^*^*

 

++Part 4, CUCM repeats the same process for MTP and Side B ++


20:41:48.468 |MediaTerminationPointControl(31)::getResourcesAllocated -- Logging

RegionB=SYS_GK_REG01 Caps and MTP/XCoder Region=FELHM_MILHA_REG01 Caps|32,100,63,1.170805^10.105.40.200^*
20:41:48.468 |MediaTerminationPointControl(31)::logCapabilitiesinTrace -- MTP/XCoder Device Caps = 4 2 16 11 12 257 259 261 |32,100,63,1.170805^10.105.40.200^*
20:41:48.468 |MediaTerminationPointControl(31)::logCapabilitiesinTrace -- Device Caps = 2 3 4 5 6 7 8 9 10 11 12 15 16 18 19 20 25 42 86 89 40 41 43 44 |32,100,63,1.170805^10.105.40.200^*
20:41:48.468 |RegionsServer::MatchCapabilities -- kbps=8, capACount=24, capBCount=8|*^*^*
20:41:48.468 |MediaTerminationPointControl(31)::getResourcesAllocated -- match1=3 match2=3|32,100,63,1.170805^10.105.40.200^*

 

++ Based on the evaluation above we can see that both sides A and B are configured to so G729 to the Xcoder. ( Remember point 5 above)- One side needs to be G711 ( if this is a xcoder used as MTP).

 

++ Hence CUCM throws up an error +++


20:41:48.468 |MediaTerminationPointControl(31)::getResourcesAllocated - ERROR LBR not support on DeviceName=SYS_MILHA_TX_01 Ci=540685347|32,100,63,1.170805^10.105.40.200^

 

Here is another rule of thumb for IOS MTP allocation: The codec configured for the MTP is what will be negotiated. If a G711MTP is configured, G711 is used ( hence both devices should talk G711 to the MTP, if a G729 MTP is used, G729 is used 

 

Example 2:

++ IOS MTP Allocation failure ++

 

Part 1 ++ CUCM selects MTP device, allocates a CI +++

 

12/08/2012 04:40:42.920 CCM|MediaTerminationPointControl(41)::getResourcesAllocated -- DeviceName=MTP-NG-SOFT Ci=20934509 ResourceCount=1|<CLID::StandAloneCluster><NID::172.20.9.135><CT::1,200,15,1.6780939><IP::172.20.9.137><DEV::jtapi_637><LVL::Detailed><MASK::0080>

 

++ Part 2, CUCM evaluates CAPS and region settings +++

Based on this we can see that the IOS MTP only supports G711ulaw


12/08/2012 04:40:42.920 CCM|MediaTerminationPointControl(41)::getResourcesAllocated -- Logging RegionA=REG-CHN-SIP Caps and MTP/XCoder Region=REG-NG-CHN Caps|<CLID::StandAloneCluster><NID::172.20.9.135><CT::1,200,15,1.6780939><IP::172.20.9.137><DEV::jtapi_637><LVL::Detailed><MASK::0080>
12/08/2012 04:40:42.921 CCM|MediaTerminationPointControl(41)::logCapabilitiesinTrace -- MTP/XCoder Device Caps = 4 257 259 261 |<CLID::StandAloneCluster><NID::172.20.9.135><CT::1,200,15,1.6780939><IP::172.20.9.137><DEV::jtapi_637><LVL::Detailed><MASK::0080>
12/08/2012 04:40:42.921 CCM|MediaTerminationPointControl(41)::logCapabilitiesinTrace -- Device Caps = 4 |<CLID::StandAloneCluster><NID::172.20.9.135><CT::1,200,15,1.6780939><IP::172.20.9.137><DEV::jtapi_637><LVL::Detailed><MASK::0080>
12/08/2012 04:40:42.921 CCM|RegionsServer::MatchCapabilities -- kbps=64, capACount=1, capBCount=4|<CLID::StandAloneCluster><NID::172.20.9.135><LVL::Detailed><MASK::0800>

 

++ Part 3, Region B ++
12/08/2012 04:40:42.921 CCM|MediaTerminationPointControl(41)::getResourcesAllocated -- Logging RegionB=REG-NG-CHN Caps and MTP/XCoder Region=REG-NG-CHN Caps|<CLID::StandAloneCluster><NID::172.20.9.135><CT::1,200,15,1.6780939><IP::172.20.9.137><DEV::jtapi_637><LVL::Detailed><MASK::0080>
12/08/2012 04:40:42.921 CCM|MediaTerminationPointControl(41)::logCapabilitiesinTrace -- MTP/XCoder Device Caps = 4 257 259 261 |<CLID::StandAloneCluster><NID::172.20.9.135><CT::1,200,15,1.6780939><IP::172.20.9.137><DEV::jtapi_637><LVL::Detailed><MASK::0080>
12/08/2012 04:40:42.921 CCM|MediaTerminationPointControl(41)::logCapabilitiesinTrace -- Device Caps = 4 2 |<CLID::StandAloneCluster><NID::172.20.9.135><CT::1,200,15,1.6780939><IP::172.20.9.137><DEV::jtapi_637><LVL::Detailed><MASK::0080>
12/08/2012 04:40:42.921 CCM|RegionsServer::MatchCapabilities -- kbps=8, capACount=2, capBCount=4|<CLID::StandAloneCluster><NID::172.20.9.135><LVL::Detailed><MASK::0800>

 

++ Now we see why this failed. Because this is a G711 IOS MTP, both sides must talk G711 to the MTP. In this case once side is configured to use G729 and the other side G711, hence MTP allocation failed. Here is the error that CUCM throws


12/08/2012 04:40:42.921 CCM|MediaTerminationPointControl(41)::getResourcesAllocated -- No matching caps for either side A or side B, MTP not allocated|<CLID::StandAloneCluster><NID::172.20.9.135><CT::1,200,15,1.6780939><IP::172.20.9.137><DEV::jtapi_637><LVL::Detailed><MASK::0080>
12/08/2012 04:40:42.921 CCM|MediaTerminationPointControl(41)::getResourcesAllocated -- match1=1 match2=0|<CLID::StandAloneCluster><NID::172.20.9.135><CT::1,200,15,1.6780939><IP::172.20.9.137><DEV::jtapi_637><LVL::Detailed><MASK::0080>
12/08/2012 04:40:42.921 CCM|MediaTerminationPointControl(41)::getResourcesAllocated -- allocateErrBitset=0x40|<CLID::StandAloneCluster><NID::172.20.9.135><CT::1,200,15,1.6780939><IP::172.20.9.137><DEV::jtapi_637><LVL::Detailed><MASK::0080>
12/08/2012 04:40:42.921 CCM|MediaTerminationPointControl(41)::SendMTPResourceErrToSender - ERROR AllocateMtpResourceReq failed -- Ci=20934509, errBitset=0x44|<CLID::StandAloneCluster><NID::172.20.9.135><CT::1,200,15,1.6780939><IP::172.20.9.137><DEV::jtapi_637><LVL::Error><MASK::0080>

 

Example 3: ( Home work):)

 

++ Wrong transcoder allocated ++

 

Can you figure out why the device named NGUK012_TX_02 was allocated? and why the other transcoders failed in this trace...

 

02:13:21.250 |MediaTerminationPointControl(31)::waiting_AllocateMtpResourceReq - (capCount,region),A(2,FELHM_MILHA_REG01),B(3,FELHM_MILHA_REG01), reqDevCap=0x0, reqMandatoryCaps=0x0, supDevCap=0x129, passthru=0, resourceCount=1|32,100,230,1.194880^10.105.40.74^*
02:13:21.250 |MediaTerminationPointControl(31)::getResourcesAllocated -- DeviceName=SYS_MILHA_TX_01 Ci=477085620 ResourceCount=1|32,100,230,1.194880^10.105.40.74^*
02:13:21.250 |MediaTerminationPointControl(31)::getResourcesAllocated -- Logging RegionA=FELHM_MILHA_REG01 Caps and MTP/XCoder Region=FELHM_MILHA_REG01 Caps|32,100,230,1.194880^10.105.40.74^*
02:13:21.250 |MediaTerminationPointControl(31)::logCapabilitiesinTrace -- MTP/XCoder Device Caps = 4 2 16 11 12 257 259 261 |32,100,230,1.194880^10.105.40.74^*
02:13:21.250 |MediaTerminationPointControl(31)::logCapabilitiesinTrace -- Device Caps = 112 4 |32,100,230,1.194880^10.105.40.74^*
02:13:21.250 |RegionsServer::MatchCapabilities -- kbps=8, capACount=2, capBCount=8|*^*^*
02:13:21.250 |MediaTerminationPointControl(31)::getResourcesAllocated -- Logging RegionB=FELHM_MILHA_REG01 Caps and MTP/XCoder Region=FELHM_MILHA_REG01 Caps|32,100,230,1.194880^10.105.40.74^*
02:13:21.250 |MediaTerminationPointControl(31)::logCapabilitiesinTrace -- MTP/XCoder Device Caps = 4 2 16 11 12 257 259 261 |32,100,230,1.194880^10.105.40.74^*
02:13:21.250 |MediaTerminationPointControl(31)::logCapabilitiesinTrace -- Device Caps = 114 11 12 |32,100,230,1.194880^10.105.40.74^*
02:13:21.250 |RegionsServer::MatchCapabilities -- kbps=8, capACount=3, capBCount=8|*^*^*
02:13:21.250 |MediaTerminationPointControl(31)::getResourcesAllocated -- No matching caps for either side A or side B, MTP not allocated|32,100,230,1.194880^10.105.40.74^*
02:13:21.250 |MediaTerminationPointControl(31)::getResourcesAllocated -- match1=0 match2=2|32,100,230,1.194880^10.105.40.74^*
02:13:21.250 |MediaTerminationPointControl(31)::getResourcesAllocated -- allocateErrBitset=0x20|32,100,230,1.194880^10.105.40.74^*
02:13:21.250 |MediaTerminationPointControl(31)::SendMTPResourceErrToSender - ERROR AllocateMtpResourceReq failed -- Ci=477085620, errBitset=0x24|32,100,230,1.194880^10.105.40.74^*
02:13:21.254 |MediaTerminationPointControl(2)::waiting_AllocateMtpResourceReq - (capCount,region),A(2,FELHM_MILHA_REG01),B(3,FELHM_MILHA_REG01), reqDevCap=0x0, reqMandatoryCaps=0x0, supDevCap=0x109, passthru=0, resourceCount=1|32,100,230,1.194880^10.105.40.74^*
02:13:21.254 |MediaTerminationPointControl(2)::getResourcesAllocated -- DeviceName=NGUK012_TX_02 Ci=477085620 ResourceCount=1|32,100,230,1.194880^10.105.40.74^*
02:13:21.254 |MediaTerminationPointControl(2)::getResourcesAllocated -- Logging RegionA=FELHM_MILHA_REG01 Caps and MTP/XCoder Region=NGUK012_REG01 Caps|32,100,230,1.194880^10.105.40.74^*
02:13:21.254 |MediaTerminationPointControl(2)::logCapabilitiesinTrace -- MTP/XCoder Device Caps = 4 2 16 11 12 257 259 261 |32,100,230,1.194880^10.105.40.74^*
02:13:21.254 |MediaTerminationPointControl(2)::logCapabilitiesinTrace -- Device Caps = 112 4 |32,100,230,1.194880^10.105.40.74^*
02:13:21.254 |RegionsServer::MatchCapabilities -- kbps=64, capACount=2, capBCount=8|*^*^*
02:13:21.254 |MediaTerminationPointControl(2)::getResourcesAllocated -- Logging RegionB=FELHM_MILHA_REG01 Caps and MTP/XCoder Region=NGUK012_REG01 Caps|32,100,230,1.194880^10.105.40.74^*
02:13:21.254 |MediaTerminationPointControl(2)::logCapabilitiesinTrace -- MTP/XCoder Device Caps = 4 2 16 11 12 257 259 261 |32,100,230,1.194880^10.105.40.74^*
02:13:21.254 |MediaTerminationPointControl(2)::logCapabilitiesinTrace -- Device Caps = 114 11 12 |32,100,230,1.194880^10.105.40.74^*
02:13:21.254 |RegionsServer::MatchCapabilities -- kbps=64, capACount=3, capBCount=8|*^*^*
02:13:21.254 |MediaTerminationPointControl(2)::getResourcesAllocated -- match1=1 match2=2|32,100,230,1.194880^10.105.40.74^*
02:13:21.254 |MediaTerminationPointControl(2)::getResourcesAllocated -- DeviceName=NGUK012_TX_02 Ci=477085620 ResourceAllocated=1|32,100,230,1.194880^10.105.40.74^*
02:13:21.254 |MediaTerminationPointControl(2)::getResourcesAllocated -- allocateErrBitset=0x0|32,100,230,1.194880^10.105.40.74^*
02:13:21.254 |MediaTerminationPointControl(2)::waiting_AllocateMtpResourceReq - MTP usage (-1) >= configured throttle percent (95) of Total Resources (10). Attempt to allocate a diffferent MTP.|32,100,230,1.194880^10.105.40.74^*
02:13:21.254 |MediaTerminationPointControl(2)::incRequestsThrottledCounter Count=1|32,100,230,1.194880^10.105.40.74^*
02:13:21.254 |MediaTerminationPointControl(2)::SendMTPResourceErrToSender - ERROR AllocateMtpResourceReq failed -- Ci=477085620, errBitset=0x2|32,100,230,1.194880^10.105.40.74^*
02:13:21.257 |MediaTerminationPointControl(2)::waiting_AllocateMtpResourceReq - (capCount,region),A(2,FELHM_MILHA_REG01),B(3,FELHM_MILHA_REG01), reqDevCap=0x0, reqMandatoryCaps=0x0, supDevCap=0x109, passthru=0, resourceCount=1|32,100,230,1.194880^10.105.40.74^*
02:13:21.257 |MediaTerminationPointControl(2)::getResourcesAllocated -- DeviceName=NGUK012_TX_02 Ci=477085620 ResourceCount=1|32,100,230,1.194880^10.105.40.74^*
02:13:21.257 |MediaTerminationPointControl(2)::getResourcesAllocated -- Logging RegionA=FELHM_MILHA_REG01 Caps and MTP/XCoder Region=NGUK012_REG01 Caps|32,100,230,1.194880^10.105.40.74^*
02:13:21.257 |MediaTerminationPointControl(2)::logCapabilitiesinTrace -- MTP/XCoder Device Caps = 4 2 16 11 12 257 259 261 |32,100,230,1.194880^10.105.40.74^*
02:13:21.257 |MediaTerminationPointControl(2)::logCapabilitiesinTrace -- Device Caps = 112 4 |32,100,230,1.194880^10.105.40.74^*
02:13:21.257 |RegionsServer::MatchCapabilities -- kbps=64, capACount=2, capBCount=8|*^*^*
02:13:21.257 |MediaTerminationPointControl(2)::getResourcesAllocated -- Logging RegionB=FELHM_MILHA_REG01 Caps and MTP/XCoder Region=NGUK012_REG01 Caps|32,100,230,1.194880^10.105.40.74^*
02:13:21.257 |MediaTerminationPointControl(2)::logCapabilitiesinTrace -- MTP/XCoder Device Caps = 4 2 16 11 12 257 259 261 |32,100,230,1.194880^10.105.40.74^*
02:13:21.257 |MediaTerminationPointControl(2)::logCapabilitiesinTrace -- Device Caps = 114 11 12 |32,100,230,1.194880^10.105.40.74^*
02:13:21.257 |RegionsServer::MatchCapabilities -- kbps=64, capACount=3, capBCount=8|*^*^*
02:13:21.257 |MediaTerminationPointControl(2)::getResourcesAllocated -- match1=1 match2=2|32,100,230,1.194880^10.105.40.74^*
02:13:21.257 |MediaTerminationPointControl(2)::getResourcesAllocated -- DeviceName=NGUK012_TX_02 Ci=477085620 ResourceAllocated=1|32,100,230,1.194880^10.105.40.74^*
02:13:21.257 |MediaTerminationPointControl(2)::getResourcesAllocated -- allocateErrBitset=0x0|32,100,230,1.194880^10.105.40.74^*
02:13:21.257 |MediaTerminationPointControl(2)::handleMtpDeviceFound|32,100,230,1.194880^10.105.40.74^*
02:13:21.257 |MediaTerminationPointControl(2)::logResourceStatusinTrace -- Device Name=NGUK012_TX_02 ResourceAvailable=11 ResourceUsed=-1|32,100,230,1.194880^10.105.40.74^*
02:13:21.257 |MediaTerminationPointControl(2)::handleMtpDeviceFound ConversationId=536954420 CI=477085620 Allocated resource=1 Device Capability = 265|32,100,230,1.194880^10.105.40.74^*
02:13:21.257 |MediaTerminationPointControl(2)::incActiveCounter - Count=1|32,100,230,1.194880^10.105.40.74^*
02:13:21.257 |MediaTerminationPointControl(2)::decAvailableCounter - Count=1|32,100,230,1.194880^10.105.40.74^*
02:13:21.257 |MediaTerminationPointControl(2)::logResourceStatusinTrace -- Device Name=NGUK012_TX_02 ResourceAvailable=10 ResourceUsed=0|32,100,230,1.194880^10.105.40.74^*
02:13:21.261 |MediaTerminationPointControl(2) - MediaExchangeAgenaAssociateReq confId=536954420 inserted AIF(15003,0)|28,100,225,15003.1^*^

 

Please rate all useful posts

+5 my friend for excellent analysis.

Likewise with the excellent analysis!

 

With your permission, I'm going to capture this (and sanitize it) and use it to show my students how to analyze MRM issues.

Hey Maren,

 

Please feel free, its my pleasure to help

Please rate all useful posts

Thanks Ayodeji Okanlawonfor excellent analysis. This is get me going. Thanks so much for your support any way. 

 

Hello Ayodeji, 

 

I'm having an issue with calls between two CUCM cluster using a SIP Trunk. Cluster A is 172.17.240.4 and cluster B is 172.16.100.2. The calling number is 5590 register to Cluster A and the called number is 5080 register to Cluster B. 

 

The issue is random. The call fails sometimes, not always. For this example, I have a working call and a not working call. 

 

The non-working call was at 14:48:52 on Cluster A and Cluster 15:02:12. On Translator X I'm able to see the SIP messaging going out from Cluster A to B. However, cluster B does not reply that invite sent by cluster A. Customer says that when this happened, they do not hear the ringing and hang up the call from the originating device. Looking at the logs I'm able to see some MTP error: 

 

04923101.016 |14:48:52.491 |AppInfo |MediaTerminationPointControl(1)::getResourcesAllocated -- No matching caps for either side A or side B, MTP not allocated

 

04923103.002 |14:48:52.492 |AppInfo |MRM::waiting_AllocateMtpResourceErr - ERROR - no resources are available -- ci = 18810903


At this point, I'm not sure if the call fails because the MTP not being allocated or because they are not getting the SIP reply from cluster B. I'm saying this because a working call (same clusters and calling/called numbers) also shows the MTP error but the call got established see below: 

 

Time Cluster A: 14:51. Time Cluster B: 15:05. 

 

04926572.016 |14:51:36.944 |AppInfo |MediaTerminationPointControl(1)::getResourcesAllocated -- No matching caps for either side A or side B, MTP not allocated

 

04926572.019 |14:51:36.944 |AppInfo |MediaTerminationPointControl(1)::SendMTPResourceErrToSender - ERROR AllocateMtpResourceReq failed -- Ci=18810957, errBitset=0x64

 

I have attached the logs. Thanks in advanced for your help! 

 

Hello! 

 

What are codec caps?

 

Thanks!

 

Laz