CTMS - Basic Interop troubleshooting

Blog

Nov 19, 2010 10:30 AM
Nov 19th, 2010

In this document we will describe the main components to understand  and troubleshoot an existing Cisco TelePresence Interop environment.

We provided Interop capabilities since version 1.3 and CTMS 1.1.  After Tandberg acquisition and the needs for any company to integrate  their existing HD video equipment with Cisco solutions, we decided to  integrate HD interop in 1.6 release, in this release we support 720p  high definition interoperability  between Cisco TelePresence systems and  other vendors. This is accomplished using CUVC 5200 series running 7.0. There are future plans and integration options for Cisco and other vendors, I will suggest to keep track of the latest news in Cisco website or via your Local Account team.


In this post we will cover the main components of one of the most common scenarios in the field.

We assume the configuration guide has been already revised carefully.

http://www.cisco.com/en/US/docs/telepresence/multipoint_switch/1_7/administration/guide/interop.html#wp1057490

Lets start reviewing the call flow for this example:


Interop.png


Versions used:

CUCM  8.0.3

CTMS 1.7.0

CTS 1.7.0

CUVC 7.1.2

CUVC-M 7.1.2

Tandberg MXP 1700 F9.0 PAL, Security


Overview


For  this test, we have 2 CTS Endpoints  dialing CTMS static bridge, CTMS  will start a new call to CUVC-M meetings range. CUVC-M will select an  available MCU, CUVC 5230. Once this happens CTMS and CUVC 5230 will  connect media directly

It is important to mention that CUVC-M is optional, some  deployments there is no CUVC-M and CTMS will connect to one or more CUVC  directly. Third party endpoints or non- CTS systems, will not dial the  CTMS range number, they will dial directly into the CUVC meeting id. In this case we have different Tandberg endpoints registered to a VCS system. Tandberg will dial CUVC directly and call is routed via VCS and Gatekeepers


Call flow for CTS to CTMS bridge


CTS endpoints in this enterprise environment will dial  directly into CTMS static bridge/scheduled interop bridge. In B2B deployments you will see different CUCM clusters and ASR or GSR SBCs in the path before we reach to our destination CTMS, this document does not cover those scenarios.


CUCM configuration

Route pattern to CTMS static bridge, this SIP trunk points directly to CTMS server


CUCMroutepattern.png

Route pattern to CUVC-M static bridge, this SIP trunk points directly to CUVC-M


CUCM-CUVCroutepattern.png


Call flow for CTMS and CUVC bridge

Once an Interop meeting is created, CTMS will generate a new call  to CUVC-M (CUVC for non CUVC-M deployments), for this it will use the  number configured under Interop number field


Static bridge configuration:


staticmeeting.png


CTMS create a new SIP connection to its CUCM and CUCM will handle the call from there.


Note: We will see this Interop number in outgoing INVITE found in  the CTMS SIP logs. Note that these Interop meetings are configured as  non-secure.


Call flow for CTMS, CUVC and CUVC-M bridge


CUVC actually uses SIP to handle the incoming meeting request  call from CTMS. In CUVC configuration guide you will see SIP Server’s IP  address. This value is actually CUCM’s IP address rather than CUVCM.  Why CUCM’s IP address? On CUCM, the outbound SIP Trunk for the bridge  call points to CUVCM’s IP. However, in this setup, CUVCM doesn’t  actually behave like a SIP B2BUA (Back to Back User Agent), instead it  simply takes the SIP messages that it receives from CUCM and passes that  information onto CUVC, without modifying the relevant SIP headers



Debugs to collect

From CTS side:

SysOp logs and Log files

From CTMS side:


Make sure your logs are set to the default level of INFO:

Download ALL Logs, most important logs to take a look:

ctms_sysop.log

sip.log

ccs.log

alarm.log



Please check for more information

https://supportforums.cisco.com/docs/DOC-13583


From CUCM side:


CUCM SDI and SDL detailed traces

Please check for more information

https://supportforums.cisco.com/community/netpro/collaboration-voice-video/telepresence

From CUVC-M side:


1) C:\Program Files\Cisco\Unified Videoconferencing Manager\Unified Videoconferencing H.323 Gatekeeper\Log\GK
2) C:\Program Files\Cisco\Unified Videoconferencing Manager\Unified Videoconferencing H.323 Gatekeeper\Log\MC
3) C:\Program Files\Cisco\Unified Videoconferencing Manager\CUVCMRM\sipserver\logs
4) C:\Program Files\Cisco\Unified Videoconferencing Manager\CUVCMRM\jboss\server\default\log


To trace calls, we will use Gatekeeper logs to trace H323/RAS and we will use the sipserver logs to trace SIP calls.


From CUVC side:


In order to enable enhanced logging, via Web go to Advanced Parameters-> CS Logging and enter Start.

Start the meeting

Click on the option “Contact Customer Support” and click in  Create download the zip file, then you will be prompted to download this  file.


Log analysis

Once you have collected logs described above, lets take a look to understand what happens?

From CTS SysOp logs:

As described before, First CTS endpoint will dial static bridge number:


CTS endpoints dials to CTMS

2010-11-19 12:10:17: INFO Local user dialing 14082323790
2010-11-19 12:10:17: INFO Negotiated Media Configuration: LTRP: Enabled GDR: Enabled High Profile: Disabled Cabac: Enabled
2010-11-19 12:10:17:
INFO Endpoint used protocol MUX version 7 for this call
2010-11-19 12:10:17: INFO The presentation has been negotiated to 5 FPS
2010-11-19 12:10:17: INFO Bandwidth Negotiated: Local Bandwidth/Remote Bandwidth/Negotiated Bandwidth=2250000/2250000/2750000, Presentation Bandwidth=500000,
# of displays=1, Remote Topology=3

From CUCM SDI traces:

We match Route Pattern pointing to CTMS Server


12:10:17.981 |Digit analysis: match(pi="2", fqcn="2323488", cn="2323488",plv="5", pss="TSBU:Alpha_Hosted:MeetMe-Hosted:DTLab", TodFilteredPss="TSBU:Alpha_Hosted:MeetMe-Hosted:DTLab", dd="14082323790",dac="0")|2,100,56,1.1694863^10.35.204.91^SEP001DA2392141
12:10:17.982 |Digit analysis: analysis results|2,100,56,1.1694863^10.35.204.91^SEP001DA2392141
12:10:17.982 ||PretransformCallingPartyNumber=2323488
|CallingPartyNumber=2323488
|DialingPartition=Alpha_Hosted
|DialingPattern=140823237[89]X

|FullyQualifiedCalledPartyNumber=14082323790

.

.

.

12:10:17.982 |SMDMSharedData::findLocalDevice - Name=Trunk_To_CTMS4 Key=4d900c5d-78a2-1b24-df9c-909f306ac0ef isActvie=1 Pid=(2,65,30) found|2,100,56,1.1694863^10.35.204.91^SEP001DA2392141

12:10:17.987 |//SIP/SIPHandler/ccbId=0/scbId=0/sip_start_timer:  type=SIP_TIMER_TRYING value=500  retries=8|2,100,56,1.1694863^10.35.204.91^SEP001DA2392141


12:10:17.987 |//SIP/SIPTcp/wait_SdlSPISignal: Outgoing SIP TCP message to 10.35.194.44 on port 5060 index 30747
INVITE sip:14082323790@10.35.194.44:5060 SIP/2.0

Verify no other Route Pattern overlaps via Route Plan report and that FAC or CMC are not enabled

.

This is a sample from SDL when calls are failing and FAC checkbox is enabled, this will prevent calls to be sent to CTMS via CTS


000008166| 2009/08/06 14:33:48.374| 001| SdlSig    | SsInfoInd                            
| wait                          | FacCmcManager(1,100,157,1)      | Cdcc(1,100,171,21)   
| (1,100,43,1).581-(
SEP001DA32B83C4:10.1.10.12)| [R:NP - HP: 0, NP: 0, LP: 0, VLP: 0, LZP:0 DBP: 0]Type=16777237 Key=0 NodeId1=1
Party1=32294406 DevId1=(1,137,1)DevName1=SEP001DA32B83C4 linePattern= linePartition= FeatAct=121 NodeId2=1 Party2=0 DevId2=(0,0,0)
DevName2= transID=0 priParty=0 totalMsg=0 featCallTypes=0 ss1DevType=4 ss2DevType=8 LineInstance=0 encodingType=0 altScript=F
deviceLocale=-72515583 PL=5 PLDmn=0 secureStatusInfo.isSet=F secureStatusInfo.Stat=0 deviceXSIIconSupported=F
lineControlPID=(0,0,0)blfDn=  videoCall=FDevModel= 255

.

.

.

CTMS answers the call and send capabilities in 200 OK message to CUCM, CUCM forwards those to CTS. If you are the first Endpoint and have selfview enabled you will be able to see yourself via mirror option in CUVC.

.

.

12:10:18.031 |//SIP/SIPTcp/wait_SdlSPISignal: Outgoing SIP TCP message to 10.35.204.91 on port 44629 index 182
SIP/2.0 200 OK
Via: SIP/2.0/TLS 10.35.204.91:44629;branch=z9hG4bK0c5a56e4
From: "2323488" <sip:2323488@10.35.194.12>;tag=001da23921413b043f317f3c-4d809704
To: <sip:14082323790@10.35.194.12>;tag=e614205a-b2f8-488c-a6dd-70a296684bab-39974559
Date: Thu, 18 Nov 2010 20:10:17 GMT
Call-ID: 001da239-21410010-143711dc-486dd981@10.35.204.91
CSeq: 101 INVITE
Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY
Allow-Events: presence, kpml
Contact: <sip:14082323790@10.35.194.12:5061;transport=tls>
Supported: replaces
Call-Info: <urn:x-cisco-remotecc:callinfo>; security= NotAuthenticated; orientation= to; gci= 2-138924; call-instance= 1
Send-Info: conference
Remote-Party-ID: "CTMS4" <sip:14082323790@10.35.194.12>;party=called;screen=yes;privacy=off
Content-Type: application/sdp
Content-Length: 507
v=0
o=CiscoSystemsCCM-SIP 2000 1 IN IP4 10.35.194.12
s=SIP Call
c=IN IP4 10.35.194.4

t=0 0

m=audio 16872 RTP/AVP 96 101

b=TIAS:64000

a=rtpmap:96 mpeg4-generic/48000

a=fmtp:96 profile-level-id=16;streamtype=5;config=B98C00;mode=AAC-hbr;sizeLength=13;indexLength=3;indexDeltaLength=3;constantDuration=480

a=rtpmap:101 telephone-event/8000

a=fmtp:101 0-15

m=video 16874 RTP/AVP 112

b=TIAS:2250000

a=rtpmap:112 H264/90000

a=fmtp:112 profile-level-id=4D0028;packetization-mode=1

a=mid:227796888

|2,100,61,2974.1^*^*



How the CTMS server INVITE to CUVC looks like:


12:10:20.380 |//SIP/SIPTcp/wait_SdlReadRsp: Incoming SIP TCP message from 10.35.194.44 on port 35216 index 30748 with 1263 bytes:
INVITE sip:82323790%23*%23000@10.35.194.12 SIP/2.0
Via: SIP/2.0/TCP 10.35.194.44:5060;branch=z9hG4bK7bff5c76
From: "CTMS4" <sip:14082323780@10.35.194.12>;tag=0024818a1826007d1a2b84f9-16345c1f
To: <sip:82323790%23*%23000@10.35.194.12>

.

.

.


Again, note that “%23*%23000” is simply “#*#000” in URL format. Why URL format? SIP is very similar to HTTP, which uses URLs to locate resources. When the relevant CUCM receives this SIP message, it knows to read this portion of the DNIS as “#*#000”, because it coded to read it as a URL.


From CUCM SDI traces


12:10:20.384 |Digit analysis: match(pi="2", fqcn="", cn="14082323780",plv="5", pss="Alpha_CUVC", TodFilteredPss="Alpha_CUVC", dd="82323790#*#000",dac="0")|2,100,56,1.1694875^10.35.194.44^*
12:10:20.384 |Digit analysis: analysis results|2,100,56,1.1694875^10.35.194.44^*
12:10:20.384 ||PretransformCallingPartyNumber=14082323780
|CallingPartyNumber=14082323780
|DialingPartition=Alpha_CUVC
|DialingPattern=823237[89]X[#][*][#]000


We find the trunk to CUVC-M, or CUVC if no CUVC-M


12:10:20.384 |SMDMSharedData::findLocalDevice - Name=Trunk_To_AlphaCUVCM1 Key=20bdfbe5-9008-6949-1142-7457fa52d339 isActvie=1 Pid=(2,65,12) found|2,100,56,1.1694875^10.35.194.44^*


We contact CUVC-M via SIP


12:10:20.387 |//SIP/SIPTcp/wait_SdlSPISignal: Outgoing SIP TCP message to 10.35.194.111 on port 5060 index 30749
INVITE sip:82323790%23*%23000@10.35.194.111:5060 SIP/2.0
Via: SIP/2.0/TCP 10.35.194.12:5060;branch=z9hG4bK101224c0a4537
From: "CTMS4" <sip:14082323780@10.35.194.12>;tag=e614205a-b2f8-488c-a6dd-70a296684bab-39974562
To: <sip:82323790%23*%23000@10.35.194.111>

.

.

.

From SIP logs in CUVC-M

To trace calls, we will use Gatekeeper logs to trace H323/RAS and we will use the sipserver logs to trace SIP calls. Before we dive into traces, we need to understand a few critical pieces of information. The next few paragraphs are very important to understand.

First, we need to understand that CUVC has been configured to have both H323 & SIP protocol stacks enabled and configured. We can see this in CUVC GUI (http://cuvcip) > Configuration > Protocols:

CUVCprotocols.png

Why does CUVC need to have both H323 & SIP configured?

CUVC & H323:

RAS/H323 is used when CUVC calls/outdials to an HD/SD IP based endpoint. The H323 messages actually terminate on CUVCM. CUVC first sends a Registration Request to CUVCM (its Gatekeeper) when it wants to perform the outdial. CUVCM responds with a Registration Confirm. Then, an H323 call is placed from CUVC to the HD/SD endpoint as follows:

CUVC -> CUVCM (ECS H323 Gatekeeper) -> IOS Gatekeeper ->H323 network -> HD/SD Endpoint

If you look at the previous CUVC Screenshot, you will see the field titled “Gatekeeper address”. That should be IP address of CUVCM, because CUVCM is CUVC’s Gatekeeper.

CUVC & SIP:

CUVC actually uses SIP to handle the incoming “bridge” call from CTMS. This is important to understand.  In the previous CUVC Screenshot, you will see the SIP Server’s IP address. This value is actually CUCM’s IP address rather than CUVCM. Why CUCM’s IP address? On CUCM, the outbound SIP Trunk for the bridge call points to CUVCM’s IP. However, in this setup, CUVCM doesn’t actually behave like a SIP B2BUA (Back to Back User Agent), instead it simply takes the SIP messages that it receives from CUCM and passes that information onto CUVC, without modifying the relevant SIP headers (via, etc).

SIP message from CUCM is recieved

2010-11-18 12:10:20.141 [.INFO] [..MESSAGE] <--- 10.35.194.12:35973 1
2010-11-18 12:10:20.141 [.INFO] [..MESSAGE] <--- INVITE sip:82323790%23*%23000@10.35.194.111:5060 SIP/2.0
2010-11-18 12:10:20.141 [.INFO] [..MESSAGE] Via: SIP/2.0/TCP 10.35.194.12:5060;branch=z9hG4bK101224c0a4537
2010-11-18 12:10:20.141 [.INFO] [..MESSAGE] From: "CTMS4" <sip:14082323780@10.35.194.12>;tag=e614205a-b2f8-488c-a6dd-70a296684bab-39974562
2010-11-18 12:10:20.141 [.INFO] [..MESSAGE] To: <sip:82323790%23*%23000@10.35.194.111>

From Jboss server logs in CUVC-M.

Make sure TelePresence Support option is checked for your range

cuvcm.png

server.log*

2010-11-18 12:10:20,172 INFO  [DEVI] RE  SipNotification.SipNewCallNotiInfo - SID:547  GUCID:DCF723800001000000000B2E0CC2230A F:sip:14082323780@10.35.194.12  T:sip:82323790#*#000@10.35.194.111  LID:dcf72380-ce51882c-8f0f-cc2230a@10.35.194.12 HASH:21133132
2010-11-18 12:10:20,172 INFO  [CORE] Notify event 'SipNewCallNotiInfo' with queue topic 'AUTH:82323790#*#000'
2010-11-18 12:10:20,172 INFO  [CORE] Notify event 'SipNewCallNotiInfo' HASH:21133132
2010-11-18 12:10:20,172 INFO  [CORE] AdHocSipAuthHandler.doAuthorization() ip=10.35.194.12
2010-11-18 12:10:20,203 INFO  [CORE] AdHocSipAuthHandler.authInBound() NewSIPCallToAddress: 82323790

2010-11-18 12:10:20,250 INFO  [CORE] Set virtual conf id: 82323790

.

.

2010-11-18 12:10:20,266 INFO  [CORE] Service existed £∫8232379

.

.

2010-11-18 12:10:20,282 INFO  [CORE] VirtualConfId 82323790 starts with service prefix 8232379, and this is allowed.
2010-11-18 12:10:20,282 INFO  [CORE] check conflictWithPrefix virConfId=82323790, numberConflict=NOT_CONFLICTED

We send XML request to from CUVCM to CUVC 5230

2010-11-18 12:10:20,391 INFO  [CORE] --->MCU (10.35.194.91) LocalPort:8167
<?xml version="1.0" encoding="UTF-8"?>
<MCU_XML_API>
  <Version>Ver 3.0</Version>
  <Account>admin</Account>
  <Password>****</Password>
  <Request>
    <Create_Conference_Request>
      <RequestID>10099494</RequestID>
      <ConfPassword></ConfPassword>
      <Name>82323790</Name>
      <ChairPassword></ChairPassword>
      <Desc>82323790</Desc>
      <ConfServiceID>8232379</ConfServiceID>

      <TTL>-1</TTL>
      <StandByTimeOut>-1</StandByTimeOut>
      <MaxPorts>300</MaxPorts>
      <MinPorts>0</MinPorts>
      <ProfileID>1</ProfileID>
      <Scheduler>True</Scheduler>
      <reserveOptionalExtraPorts>0</reserveOptionalExtraPorts>
    </Create_Conference_Request>
  </Request>
</MCU_XML_API>

We recieve XML response from CUVC

2010-11-18 12:10:20,422 INFO  [CORE] Notification: Conference_Created_Notification
2010-11-18 12:10:20,422 INFO  [CORE] <---MCU (10.35.194.91) LocalPort:8167
<?xml version="1.0" encoding="UTF-8"?>
<MCU_XML_API>

.

.

.

2010-11-18 12:10:20,422 INFO  [CORE] <---MCU (10.35.194.91) LocalPort:8167
<?xml version="1.0" encoding="UTF-8"?>
<MCU_XML_API>
  <Version>Ver 7.1</Version>
  <Notification>
    <Conference_Created_Notification>

.

.

.

2010-11-18 12:10:20,422 INFO  [CORE] <---MCU (10.35.194.91) LocalPort:8167
<?xml version="1.0" encoding="UTF-8"?>
<MCU_XML_API>
  <Version>Ver 3.0</Version>
  <MsgLength>000284</MsgLength>
  <Response>
    <Create_Conference_Response>
      <RequestID>10099494</RequestID>
      <ConfGID>0001002300000000d600fce0</ConfGID>
     <ReturnValue>OK</ReturnValue>
    </Create_Conference_Response>
  </Response>
</MCU_XML_API>

From SIP logs in CUVC-M, we send SIP message response to CUCM, this includes codec supported by CUVC and other media descriptors

2010-11-18 12:10:20.594 [.INFO] [..MESSAGE] <--- 10.35.194.91:5060 0
2010-11-18 12:10:20.594 [.INFO] [..MESSAGE] <--- SIP/2.0 200 OK
2010-11-18 12:10:20.594 [.INFO] [..MESSAGE] From: "CTMS4"<sip:14082323780@10.35.194.12>;tag=5d49d70-0-13c4-2662c8-7a97d08f-2662c8
2010-11-18 12:10:20.594 [.INFO] [..MESSAGE] To: <sip:82323790#*#000@10.35.194.91>;tag=2eea9e18-a23c25b-13c4-45026-7c196-3c486d74-7c196
2010-11-18 12:10:20.594 [.INFO] [..MESSAGE] Call-ID: 5f00ac0-0-13c4-2662c8-22c34e1f-2662c8@10.35.194.12
2010-11-18 12:10:20.594 [.INFO] [..MESSAGE] CSeq: 1 INVITE
2010-11-18 12:10:20.594 [.INFO] [..MESSAGE] User-Agent: RADVISION SCOPIA MCU 7.1.2.7.0 RVID534168414743475b5c0e5d410e5512
2010-11-18 12:10:20.594 [.INFO] [..MESSAGE] Supported: replaces
2010-11-18 12:10:20.594 [.INFO] [..MESSAGE] Via: SIP/2.0/UDP 10.35.194.111:5060;branch=z9hG4bK-2662c8-95f1dda3-32ac9e35
2010-11-18 12:10:20.594 [.INFO] [..MESSAGE] Contact: <sip:82323790#*#000@10.35.194.91>;isfocus
2010-11-18 12:10:20.594 [.INFO] [..MESSAGE] Cisco-Guid: 3707184000 65536 2862 214049546
2010-11-18 12:10:20.594 [.INFO] [..MESSAGE] Allow-Events: kpml
2010-11-18 12:10:20.594 [.INFO] [..MESSAGE] Allow: INVITE,ACK,CANCEL,BYE,INFO,UPDATE,REFER,NOTIFY,SUBSCRIBE
2010-11-18 12:10:20.594 [.INFO] [..MESSAGE] Accept: application/sdp,audio/telephone-event,application/media_control+xml
2010-11-18 12:10:20.594 [.INFO] [..MESSAGE] Accept-Language: en
2010-11-18 12:10:20.594 [.INFO] [..MESSAGE] Accept-Encoding: text
2010-11-18 12:10:20.594 [.INFO] [..MESSAGE] Content-Type: application/sdp
2010-11-18 12:10:20.594 [.INFO] [..MESSAGE] Content-Length: 845
2010-11-18 12:10:20.594 [.INFO] [..MESSAGE] 
2010-11-18 12:10:20.594 [.INFO] [..MESSAGE] v=0
2010-11-18 12:10:20.594 [.INFO] [..MESSAGE] o=RV-MCU 508310940 508310940 IN IP4 10.35.194.91
2010-11-18 12:10:20.594 [.INFO] [..MESSAGE] s=RV MCU Session
2010-11-18 12:10:20.594 [.INFO] [..MESSAGE] b=AS:2250
2010-11-18 12:10:20.594 [.INFO] [..MESSAGE] t=0 0
2010-11-18 12:10:20.594 [.INFO] [..MESSAGE] m=audio 16574 RTP/AVP 119 113 9 112 8 0 101
2010-11-18 12:10:20.594 [.INFO] [..MESSAGE] c=IN IP4 10.35.194.91
2010-11-18 12:10:20.594 [.INFO] [..MESSAGE] a=rtpmap:119 MP4A-LATM/32000
2010-11-18 12:10:20.594 [.INFO] [..MESSAGE] a=fmtp:119 profile-level-id=2;object=2;bitrate=96000
2010-11-18 12:10:20.594 [.INFO] [..MESSAGE] a=rtpmap:113 G7221/32000
2010-11-18 12:10:20.594 [.INFO] [..MESSAGE] a=fmtp:113 bitrate=48000
2010-11-18 12:10:20.594 [.INFO] [..MESSAGE] a=rtpmap:9 G722/8000
2010-11-18 12:10:20.594 [.INFO] [..MESSAGE] a=rtpmap:112 G7221/16000
2010-11-18 12:10:20.594 [.INFO] [..MESSAGE] a=fmtp:112 bitrate=32000
2010-11-18 12:10:20.594 [.INFO] [..MESSAGE] a=rtpmap:8 PCMA/8000
2010-11-18 12:10:20.594 [.INFO] [..MESSAGE] a=rtpmap:0 PCMU/8000
2010-11-18 12:10:20.594 [.INFO] [..MESSAGE] a=rtpmap:101 telephone-event/8000
2010-11-18 12:10:20.594 [.INFO] [..MESSAGE] a=fmtp:101 0-16
2010-11-18 12:10:20.594 [.INFO] [..MESSAGE] a=sendrecv
2010-
11-18 12:10:20.594 [.INFO] [..MESSAGE] m=video 12266 RTP/AVP 97 34

2010-11-18 12:10:20.594 [.INFO] [..MESSAGE] c=IN IP4 10.35.194.92
2010-11-18 12:10:20.594 [.INFO] [..MESSAGE] b=TIAS:2250000
2010-11-18 12:10:20.594 [.INFO] [..MESSAGE] a=rtpmap:97 H264/90000
2010-11-18 12:10:20.594 [.INFO] [..MESSAGE] a=fmtp:97 profile-level-id=4DE028
2010-11-18 12:10:20.594 [.INFO] [..MESSAGE] a=rtpmap:34 H263/90000
2010-11-18 12:10:20.594 [.INFO] [..MESSAGE] a=fmtp:34 CIF=1;QCIF=1;CIF4=1
2010-11-18 12:10:20.594 [.INFO] [..MESSAGE] a=sendrecv

2010-11-18 12:10:20.594 [.INFO] [..MESSAGE] m=control 3337 tcp RvMcuNonStandard
2010-11-18 12:10:20.594 [.INFO] [..MESSAGE] c=IN IP4 10.35.194.91
2010-11-18 12:10:20.594 [.INFO] [..MESSAGE] a=fmtp:RvMcuNonStandard Identifier={1 3 6 1 4 1 903 300} Data={1 32 0 0 0 0 0 12 0 1 0 35 0 0 0 0 214 0 252 224}

From CTMS Logs, we need to look at ctms_sysop.log, this describes the sequence of events for first caller joining the conference call,

as you can see my Endpoint joins the call and will be place on hold automatically since it is an Interop meeting, CTMS performs the dialout,

once this call leg connects, endpoint will be resumed, if dialout fail you will be still in Hold state until next Endpoint joins. In this case I see myself in the screen after Welcome screen from CUVC (To see welcome screen you need to enable it in your conference options).

Nov 18 20:10:17 sjc01-alpha-cts-4 local4 5 : [TXNID=90]:CCS 123:Incoming call from 2323488

.

.

.

Nov 18 20:10:20 sjc01-alpha-cts-4 local4 5 : [TXNID=157]:CCS Going to dialout to URI=82323790#*#000@10.35.194.12
Nov 18 20:10:20 sjc01-alpha-cts-4 local4 5 : [TXNID=90]:CCS 123 HOLD from web received confid=9182323790
Nov 18 20:10:20 sjc01-alpha-cts-4 local4 5 : [TXNID=90,CN=9182323790,DN=2323488,rcc]:CONFMGMT Local hold
Nov 18 20:10:20 sjc01-alpha-cts-4 local4 5 : [TXNID=90,CN=9182323790,DN=2323488,Rcc]:RTP Hold-Resume epid:12Set State:Hold
Nov 18 20:10:20 sjc01-alpha-cts-4 local4 5 : -XML| unknown element or attribute name ("xsi:schemaLocation") (line=2)
Nov 18 20:10:20 sjc01-alpha-cts-4 local4 5 : [TXNID=157,CN=9182323790,DN=14082323780,a]:RTP OpenEndpoint callId:0 epid:13
Nov 18 20:10:20 sjc01-alpha-cts-4 local4 5 : [TXNID=157,CN=9182323790,DN=14082323780,a]:CONFMGMT Conference Control Protocol is not supported for this end point.
Nov 18 20:10:20 sjc01-alpha-cts-4 local4 5 : [TXNID=157,CN=9182323790,DN=14082323780,rcc]:CONFMGMT Call added to conference.
Nov 18 20:10:20 sjc01-alpha-cts-4 local4 5 : [TXNID=157]:CCS 124: Added 14082323780 to conference 9182323790
Nov 18 20:10:20 sjc01-alpha-cts-4 local4 5 : [TXNID=90]:CCS 123 RESUME from web received confid=9182323790
Nov 18 20:10:22 sjc01-alpha-cts-4 local4 5 : [TXNID=90,CN=9182323790,DN=2323488,rcc]:CONFMGMT Call is resumed locally
Nov 18 20:10:22 sjc01-alpha-cts-4 local4 5 : [TXNID=90,CN=9182323790,DN=2323488,Rcc]:RTP Hold-Resume epid:12Set State:Resume
Nov 18 20:10:22 sjc01-alpha-cts-4 local4 5 : [TXNID=157,DN=14082323780,Rep]:RTP  prev_ssrc:0x0 new_ssrc:0x:0x29a00c11 new_seq:0x17b
Nov 18 20:10:22 sjc01-alpha-cts-4 local4 5 : [TXNID=90,CN=9182323790,DN=2323488,rcc]:CONFMGMT Resuming call.
Nov 18 20:10:22 sjc01-alpha-cts-4 local4 5 : [TXNID=90]:CCS 123: REINVITE from confmgr confID=9182323790
Nov 18 20:10:22 sjc01-alpha-cts-4 local4 5 : [TXNID=90]:CCS Negotiated Audio BW=320000, Negotiated Video BW=2750000, Presentation BW=500000, Quality=3, RemoteTopo=1
Nov 18 20:10:23 sjc01-alpha-cts-4 local4 5 : [TXNID=157,DN=14082323780,Rep]:RTP  prev_ssrc:0x0x29a00c11 new_ssrc:0x:0x2fb52049 new_seq:0x2

From CUCM logs,

Second Endpoint joins the call

12:10:54.161 |Digit analysis: match(pi="2", fqcn="2323487", cn="2323487",plv="5", pss="TSBU:Alpha_Hosted:MeetMe-Hosted:DTLab", TodFilteredPss="TSBU:Alpha_Hosted:MeetMe-Hosted:DTLab", dd="14082323790",dac="0")|2,100,56,1.1694977^10.22.73.71^SEP001DA2392222
12:10:54.161 |Digit analysis: analysis results|2,100,56,1.1694977^10.22.73.71^SEP001DA2392222
12:10:54.161 ||PretransformCallingPartyNumber=2323487
|CallingPartyNumber=2323487
|DialingPartition=Alpha_Hosted
|DialingPattern=140823237[89]X
|FullyQualifiedCalledPartyNumber=14082323790

At this point you have 3 Endpoints in the call why? First CTS Endpoint exchanges Media to CTMS directly,

second Endpoint is the CUVC call leg where Tandberg 1700MXP is connected, this Tandberg exchanges media to CUVC directly, CUVC forwards this media to CTMS, third Endpoint is the CTS, which again, always talk to CTMS directly,

CTS and CUVC never talk directly as CUVC does not support TIP/MUX protocol. Third party Endpoints dont reach CTMS directly as of now.

Now that you understand the call flow, you can isolate where the failure is occuring:

Common issues:

1. Incorrect call routing in CUCM, Endpoints not able to reach directly CTMS

1a. CTMS not able to reach CUVC because of: Incoming Calling Search Space in SIP trunk, Incorrect CUCM group, MTP enabled (we never should have this option enabled)

1b Be aware of Unassigned DN, please feel free to use Dialed Number Analyzer or CUCM SDI Traces to isolate the issue.

1c Incorrect HD prefix configuration in CUCM Route Pattern

2. Incorrect HD prefix in CTMS

2a. Incorrect Policy for Meetings, Interop does not support security at the time of this writing. in CTMS option for Interop security is not configurable, but in CUVC it is.

2b. Default Meeting Settings in CTMS make sure it matches prefix in CUCM Route Pattern

3. Compatibility

3a. Check always compatibility matrix for all your components before starting troubleshooting

In next post we will go deeper in CUVC and CTMS components to isolate most complex issues.

Thanks  to Sridhar Narahari in TXBU for his cooperation

Average Rating: 0 (0 ratings)

Actions

Login or Register to take actions

This Blog

Posted November 19, 2010 at 10:30 AM
Stats:
Comments:0 Avg. Rating:0
Views:3387   
Shares:0

Related Content

Blogs Leaderboard