cc/td/doc/product/voice/vpdd/cdd
hometocprevnextglossaryfeedbacksearchhelp
PDF

Table Of Contents

Cisco CallManager Express and Survivable Remote Site Telephony Troubleshooting

Overview

PostInstallation Checklist for TAPILite

Debug Traces

Capturing a Debug Log

Analyzing Traces

Cisco CallManager Express and Survivable Remote Site Telephony Troubleshooting

This chapter contains the following topics:

• Overview

• PostInstallation Checklist for TAPILite

• Debug Traces

Overview

Figure 28 shows an architecture overview of Cisco CallManager Express (CME) and Cisco Survivable Remote Site Telephony (SRST).

Figure 28 Cisco CallManager Express and SRST Architecture Overview

Cisco CME allows small business customers and enterprise branch offices to deploy voice, data, and IP telephony on a single platform. Cisco CME supports the following APIs in addition to supporting Tcl and VoiceXML:

•SCCP— Cisco CME uses the Skinny Client Control Protocol (SCCP) to control Cisco IP phones.

•RouterXML— An extension of the Cisco AVVID XML Layer (AXL) API layer that provides a mechanism for configuring, provisioning, and monitoring Cisco CME routers.

•TAPILite (A version of TAPI)— The TAPILite layer is a lighter implementation of the full TAPI stack. It consists of a set of classes that help developers create customized telephony applications for Cisco CME.

Cisco SRST provides Cisco CallManager with fallback support for Cisco IP phones if a WAN failure is detected. Cisco SRST runs under the Cisco IOS stack and uses the Skinny protocol (SCCP) to interact with Cisco IP phones.

PostInstallation Checklist for TAPILite

Some problems may occur because of improper installation. Use this checklist to verify proper installation.

____ Ensure that Cisco CallManager is running with the correct configuration for TAPI client.
____ Ensure that the network connection is up between the Telephony Service Provider (TSP) and Cisco CallManager Express (CME).
____ Ensure that the username and password in the TSP match the username and password in Cisco CME.
____ Ensure that all devices are correctly associated with the user in Cisco CME.
____ Ensure that the Cisco TSP is the correct version.

Debug Traces

Use the debug ephone detail command to debug the output. "Capturing a Debug Log" outlines the steps required to capture a debug log using the logging buffer method. The debug traces that are analyzed in "Analyzing Traces" are captured from generic scenarios and are provided as a general road map for troubleshooting.

If the problem cannot be resolved, contact the Cisco TAC or Developer Support. For more information on opening a case with the TAC or Developer Support, see "General Troubleshooting Procedures" on page 1."

Capturing a Debug Log

If you use a logging console to capture debug output, you may not be able to capture the complete log of the output. To ensure that you capture the complete log of your debug output, use the logging buffer method as shown below:

Step 1 Configure the logging buffer.

Router# configure terminal Router(config)# no logging console Router(config)# logging buffer 2000000 Router(config)# end

Step 2 Clear the logging buffer.

Router# clear logging

Step 3 Verify the Cisco IOS release on the router, and run the configuration.

Router# show version Router# show run

Step 4 Turn on the debugs and reproduce the problem.

Step 5 Capture the debug output to a file after entering the show log command.

Router# show log

Analyzing Traces

This section consists of sample debug output for:

•The Skinny Client Control Protocol (SCCP) for Cisco IP Phone registration with Cisco SRST and Cisco CME.

•TAPILite client registration with Cisco CME.

Skinny Client Control Protocol

SRST

Following is a sample debug trace of show ephone detail where the Cisco IP phone registers with Cisco SRST after detecting a failure in Cisco CallManager.



Router# debug ephone detail EPHONE detail debugging is enabled *May 31 11:05:43.584: %IPPHONE-6-REG_ALARM: 13: Name=SEP000D287E44A9 Load=6.0(0.1) Last=CM-aborted-TCP *May 31 11:05:43.584: ephone-(3)[2] StationRegisterMessage (0/0/8) from 13.13.13.16 *May 31 11:05:43.584: ephone-(3)[2] Register StationIdentifier DeviceName SEP000D287E44A9 *May 31 11:05:43.584: ephone-3[2]:stationIpAddr 13.13.13.16 *May 31 11:05:43.584: ephone-3[2]:phone SEP000D287E44A9 re-associate OK on socket [2] *May 31 11:05:43.584: %IPPHONE-6-REGISTER_NEW: ephone-3:SEP000D287E44A9 IP:13.13.13.16 Socket:2 DeviceType:Phone has registered. *May 31 11:05:43.841: ephone-3[2]:InterogatePhone *May 31 11:05:43.841: ephone-3[2]:Sending StationServerReqMessage <= Cisco SRST contacts the IP phone and requests server information *May 31 11:05:44.098: Server List: *May 31 11:05:44.098: CM1 13.13.13.50 *May 31 11:05:44.098: CM2 0.0.0.0 <snip> *May 31 11:05:44.351: ephone-3[2][SEP000D287E44A9]:ButtonTemplate offset 0 buttons 6 total 6 <= Cisco SRST receives button template from the IP Phone *May 31 11:0 DevSup-BO-26515:44.351: ephone-3[2]:Button Type 9 *May 31 11:05:44.351: ephone-3[2]:Found Line Button 1 *May 31 11:05:44.351: ephone-3[2]:Button Type 9 *May 31 11:05:44.351: ephone-3[2]:Found Line Button 2 *May 31 11:05:44.351: ephone-3[2]:Button Type 2 <snip> *May 31 11:05:44.351: ephone-3[2]:Found Speed Dial Button 6 *May 31 11:05:44.351: ephone-3[2]:Requesting first LineStatReq *May 31 11:05:44.608: ephone-3[2][SEP000D287E44A9]:SkinnyTryCall to 2000 instance 1 start at 0

*May 31 11:05:44.608: Skinny Update dn 1 chan 2 *May 31 11:05:44.608: ephone-3[2]:SkinnyAllocateDN 1 2000 2000 *May 31 11:05:44.608: ephone-3[2]: LineStatMessage Auto Create new DN 1 line 1 *May 31 11:05:44.608: ephone-3[2]: LineStatMessage Auto Bind new DN 1 to line 1 *May 31 11:05:44.608: Skinny DN 1 chan 1 state change to UP *May 31 11:05:44.612: Skinny DN 1 chan 2 state change to UP *May 31 11:05:44.865: ephone-3[2]:Auto Bind with null phone number for line 2 *May 31 11:05:45.118: ephone-3[2]:Auto set with null speedDial 1 *May 31 11:05:45.371: ephone-3[2]:Auto set with null speedDial 2 <snip> *May 31 11:05:45.877: ephone-3[2]: SpeedDialStatMessage Auto Set completed 2 lines 4 speed *May 31 11:05:46.130: ephone-3[2]:SoftKeys ver: 3| 1 tag 1 *May 31 11:05:46.130: ephone-3[2]:SoftKeys ver: 3| 2 tag 2 <snip> *May 31 11:05:47.905: ephone-3[2]:ClearCallPrompt line 0 ref 0 *May 31 11:05:47.905: ephone-3[2]:SelectPhoneSoftKeys set 0 mask 7 for line 0 ref 0 *May 31 11:05:47.905: ephone-3[2][SEP000D287E44A9]:CallPrompt line 0 ref 0: CM Fallback Service Operating <= Cisco SRST requests the IP Phone to display the "CM Fallback Service Operating" message

*May 31 11:05:47.909: ephone-3[2]:SkinnyCheckPendingCallBackPhone scan 6 lines *May 31 11:05:47.909: ephone-3[2][SEP000D287E44A9]: DN in-service for DN 1 chan 1 *May 31 11:05:47.909: SkinnyGetCallState for DN 1 chan 1 IDLE *May 31 11:05:47.909: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0 *May 31 11:05:47.909: ephone-3[2][SEP000D287E44A9]: DN in-service for DN 1 chan 2 *May 31 11:05:47.909: SkinnyGetCallState for DN 1 chan 2 IDLE *May 31 11:05:47.909: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0 *May 31 11:05:47.921: ephone-3[2][SEP000D287E44A9]:CallPrompt line 0 ref 0: SRST *May 31 11:05:47.921: ephone-3[2][SEP000D287E44A9]:CallPrompt line 0 ref 0: CM Fallback Service Operating *May 31 11:05:47.921: ephone-3[2]:SkinnyCheckPendingCallBackPhone scan 6 lines *May 31 11:05:47.925: ephone-3[2]:TimeDateReqMessage <= Cisco SRST receives time date request from the IP phone.

*May 31 11:05:47.925: year=1993 month=5 day=31 *May 31 11:05:47.925: hour=11 minute=5 second=47 *May 31 11:05:47.925: day=1 dayofyear=151 tzoffset=0 *May 31 11:05:47.925: ephone-3[2]:DefineTimeDate sent# <=Cisco SRST sends the time date to the IP phone

Router# *May 31 11:05:57.538: ephone-3[2]:Check Hot-Sync for 6 out of 1 lines *May 31 11:05:57.538: SkinnyGetCallState for DN 1 chan 1 IDLE *May 31 11:05:57.538: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0 *May 31 11:05:57.538: ephone-3[2]:SetCallState line 1 DN 1 chan 1 ref 0 TsOnHook *May 31 11:05:57.538: ephone-3[2]:ClearCallPrompt line 1 ref 0 *May 31 11:05:57.538: ephone-3[2]:SelectPhoneSoftKeys set 0 mask 7 for line 1 ref 0 *May 31 11:05:57.538: SkinnyGetCallState for DN 1 chan 2 IDLE *May 31 11:05:57.538: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0 *May 31 11:05:57.542: ephone-3[2]:SetCallState line 1 DN 1 chan 2 ref 0 TsOnHook Router# *May 31 11:05:57.542: ephone-3[2]:ClearCallPrompt line 1 ref 0 *May 31 11:05:57.542: ephone-3[2]:SelectPhoneSoftKeys set 0 mask 7 for line 1 ref 0 *May 31 11:05:57.542: ephone-3[2]:Set MWI line 1 to OFF *May 31 11:05:57.542: ephone-3[2]:Set MWI line 0 to OFF *May 31 11:05:57.546: ephone-3[2][SEP000D287E44A9]:CallPrompt line 0 ref 0: CM Fallback Service Operating *May 31 11:05:57.546: ephone-3[2]:SkinnyCheckPendingCallBackPhone scan 6 lines Router#

Following is a sample debug trace of show ephone detail for Skinny phone registration with Cisco SRST where the Cisco IP Phone un-registers with Cisco SRST after it detects that Cisco CallManager is back in service.

Router# debug ephone detail EPHONE detail debugging is enabled

*May 31 11:06:24.110: ephone-3[2][SEP000D287E44A9]: DN out-of-service for DN 1 chan 1 *May 31 11:06:24.110: SkinnyGetCallState for DN 1 chan 1 IDLE <= Cisco SRST requests the call state for IP phone with DN 1 and channel 1.

*May 31 11:06:24.110: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0 *May 31 11:06:24.110: ephone-3[2][SEP000D287E44A9]: DN out-of-service for DN 1 chan 2 <=Cisco SRST requests the call state for IP phone with DN 1 and channel 2.

*May 31 11:06:24.110: SkinnyGetCallState for DN 1 chan 2 IDLE *May 31 11:06:24.110: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0 *May 31 11:06:24.110: Skinny DN 1 chan 1 state change to DOWN *May 31 11:06:24.110: Skinny DN 1 chan 2 state change to DOWN *May 31 11:06:24.110: Skinny set DN number on dn 1 *May 31 11:06:24.114: Skinny set DN name on dn 1 *May 31 11:06:24.114: ephone-3[2]:SkinnyFreeDN 1 *May 31 11:06:24.114: ephone-3[2]:UnregisterAck sent on socket [2] (0/0/8) <= Cisco SRST sends an unregistered acknowledgement message to the IP phone.

Router # *May 31 11:06:24.114: %IPPHONE-6-UNREGISTER_NORMAL: ephone-3:SEP000D287E44A9 IP:13.13.13.16 Socket:2


DeviceType:Phone has unregistered normally. <= Cisco SRST unregisters from Cisco CallManager. Router#

Cisco CME

Following is a sample debug trace of debug ephone detail for Skinny phone registration with Cisco CME where a Cisco IP phone with dn 3000 registers with Cisco CME.

Router#debug ephone detail EPHONE detail debugging is enabled Router# *Apr 20 00:29:34.251: ephone-(4)[1] StationRegisterMessage (3/7/20) from 200.0.0.3 <= Cisco CME receives the registration request.

*Apr 20 00:29:34.251: ephone-(4)[1] Register StationIdentifier DeviceName SEP000D287E44A9 *Apr 20 00:29:34.251: ephone-4[-1]:stationIpAddr 200.0.0.3 *Apr 20 00:29:34.251: ephone-4[-1]:socket change -1 to 1 *Apr 20 00:29:34.251: ephone-4[1]:phone SEP000D287E44A9 re-associate OK on socket [1]

*Apr 20 00:29:34.764: ephone-4[1]:SoftKeys ver: 3| 11 *Apr 20 00:29:34.764: ephone-4[1]:SoftKeys ver: 3| 12 <snip> *Apr 20 00:29:35.537: ephone-4[1]:CallPrompt line 0 ref 0: ITS *Apr 20 00:29:35.790: ephone-4[1]:Speed Dial Label 3 : PAGING ALL *Apr 20 00:29:36.042: ephone-4[1]:Speed Dial Label 2 : PAGING BR *Apr 20 00:29:36.294: ephone-4[1]:Speed Dial Label 1 : PAGING HQ *Apr 20 00:29:36.547: ephone-4[1]:TimeDateReqMessage <= Cisco CME receives the time date request

*Apr 20 00:29:36.547: year=1993 month=4 day=20 *Apr 20 00:29:36.547: hour=0 minute=29 second=36 *Apr 20 00:29:36.547: day=2 dayofyear=110 tzoffset=0 *Apr 20 00:29:36.547: ephone-4[1]:DefineTimeDate sent <= Cisco CME sends the time date request to the IP phone.

*Apr 20 00:29:44.624: ephone-4[1]:ClearCallPrompt line 0 ref 0 *Apr 20 00:29:44.624: ephone-4[1]:SelectPhoneSoftKeys set 0 for line 0 ref 0 *Apr 20 00:29:44.624: ephone-4[1]:CallPrompt line 0 ref 0: Cisco ITS <= Cisco CME notifies the IP phone to display "Cisco ITS". Cisco ITS is the old name for Cisco SRST.

*Apr 20 00:29:44.624: ephone-4[1]: DN in-service for DN 4 *Apr 20 00:29:44.624: SkinnyGetCallState for DN 4 IDLE *Apr 20 00:29:44.624: called DN -1, calling DN -1 phone -1 s2s:0 *Apr 20 00:29:44.624: Skinny DN 4 state change to UP *Apr 20 00:29:44.624: ephone-4[1]: DN in-service for DN 11 *Apr 20 00:29:44.624: SkinnyGetCallState for DN 11 IDLE *Apr 20 00:29:44.628: called DN -1, calling DN -1 phone -1 s2s:0 *Apr 20 00:29:44.628: Skinny DN 11 state change to UP *Apr 20 00:29:44.628: ephone-4[1]:Check Hot-Sync for 6 out of 2 lines *Apr 20 00:29:44.628: SkinnyGetCallState for DN 4 IDLE *Apr 20 00:29:44.628: called DN -1, calling DN -1 phone -1 s2s:0 *Apr 20 00:29:44.628: ephone-4[1]:SetCallState line 1 DN 4 ref 32 TsOnHook <= Cisco CME notifies the IP phone that it is in the ON HOOK state for line 1 DN4.

*Apr 20 00:29:44.628: ephone-4[1]:ClearCallPrompt line 1 ref 32 <= Cisco CME notifies the IP phone to clear the prompt.

*Apr 20 00:29:44.628: ephone-4[1]:SelectPhoneSoftKeys set 0 for line 1 ref 32 <= Cisco CME notifies the IP phone to update softkey mapping for line 1.

*Apr 20 00:29:44.632: SkinnyGetCallState for DN 11 IDLE *Apr 20 00:29:44.632: called DN -1, calling DN -1 phone -1 s2s:0 *Apr 20 00:29:44.632: ephone-4[1]:SetCallState line 2 DN 11 ref 13 TsOnHook <= Set line 2


DN 11 to status onhook *Apr 20 00:29:44.632: ephone-4[1]:ClearCallPrompt line 2 ref 13 *Apr 20 00:29:44.632: ephone-4[1]:SelectPhoneSoftKeys set 0 for line 2 ref 13 <= Cisco CME notifies the IP phone to update softkey mapping for line 2.

*Apr 20 00:29:44.632: ephone-4[1]:Set MWI line 1 to OFF *Apr 20 00:29:44.636: ephone-4[1]:Set MWI line 0 to OFF *Apr 20 00:29:44.636: ephone-4[1]:Set MWI line 2 to OFF Router

TAPILite

Following is a sample debug trace of debug ephone detail for TAPILite client registration with Cisco CME where a Cisco IP phone with dn 3000 registers with Cisco CME.



Router# Register Message From Tapi Client *Apr 20 01:44:48.511: ephone-1[3]:Register Message From TAPI Client 0 <= Cisco CME received registration from TAPI client.

*Apr 20 01:44:48.511: ephone-1[3]:socket change -1 to 5 *Apr 20 01:44:48.511: ephone-1[3]:socket 5 is associated to a TAPI Client 0 *Apr 20 01:44:48.511: ephone-1[3]:Username and password verified <= TAPILite Client successfully verified for TAPI Client.

*Apr 20 01:45:08.704: ephone-1[3]:Check Hot-Sync for 6 out of 2 lines *Apr 20 01:45:08.704: SkinnyGetCallState for DN 6 IDLE *Apr 20 01:45:08.704: called DN -1, calling DN -1 phone -1 s2s:0 *Apr 20 01:45:08.704: ephone-1[3]:SetCallState line 2 DN 6 ref 85 TsOnHook <= Sets line 2 DN6 to status onhook.

*Apr 20 01:45:08.704: ephone-1[3]:ClearCallPrompt line 2 ref 85 *Apr 20 01:45:08.704: ephone-1[3]:ClearCallPrompt line to Tapi Client on line 2 ref 85 <= Sends clear prompt request to TAPILite Client.

*Apr 20 01:45:08.708: ephone-1[3]:SelectPhoneSoftKeys set 0 for line 2 ref 85 *Apr 20 01:45:08.708: ephone-1[3]:Set MWI line 2 to OFF Router#

hometocprevnextglossaryfeedbacksearchhelp

Posted: Fri Sep 10 09:42:36 PDT 2004
All contents are Copyright © 1992--2004 Cisco Systems, Inc. All rights reserved.
Important Notices and Privacy Statement.