Total Pageviews

Saturday, November 19, 2011

Info about Debug Output Running in Voice Gateways

What Information can I get if I run the following debug outputs in my Voice Gateway to troubleshoot the Ephone registration issues ?
S.NoDebugs
1debug ephone register <mac-address>"
2debug ephone error mac-address <mac_addr>
3debug voip ccapi inout
4debug isdn q931
1. Using the "debug ephone register <mac_addr>" you get the following information
 This gives you detailed information on how the registration is happening in the Ephone MAC address, Retriving the xml files from the TFTP server
and the Ephone configuration file XMLDefault.cnf.xml, SEP00192F87A7C6.cnf.xml.  Ephone Registration process with Ephone Load File name using Skinny Protocol with IP address details and it gives you the Phone Registration Status.
 Sample debug output is attached.  You can run this debug whenever you have any issues in Ephone Registation.
#debug ephone register mac <mac_addr>

012095: Jan 20 19:13:23.131 GMT: TFTP: Looking for CTLSEP00192F87A7C6.tlv
012096: Jan 20 19:13:23.303 GMT: TFTP: Looking for SEP00192F87A7C6.cnf.xml
012097: Jan 20 19:13:23.415 GMT: TFTP: Looking for XMLDefault.cnf.xml
012098: Jan 20 19:13:23.415 GMT: TFTP: Opened system:/its/XMLDefault.cnf.xml, fd 0, size 1577 for process 203
012099: Jan 20 19:13:23.423 GMT: TFTP: Finished system:/its/XMLDefault.cnf.xml, time 00:00:00 for process 203
012100: Jan 20 19:13:34.779 GMT: TFTP: Looking for term70.default.loads.loads
012101: Jan 20 19:13:34.795 GMT: TFTP: Opened flash:term70.default.loads.loads, fd 0, size 642 for process 203
012102: Jan 20 19:13:34.803 GMT: TFTP: Finished flash:term70.default.loads.loads, time 00:00:00 for process 203
012103: Jan 20 19:14:19.759 GMT: TFTP: Looking for CTLSEP00192F87A7C6.tlv
012104: Jan 20 19:14:20.535 GMT: TFTP: Looking for SEP00192F87A7C6.cnf.xml
012105: Jan 20 19:14:20.643 GMT: TFTP: Looking for XMLDefault.cnf.xml
012106: Jan 20 19:14:20.647 GMT: TFTP: Opened system:/its/XMLDefault.cnf.xml, fd 0, size 1577 for process 203
012107: Jan 20 19:14:20.655 GMT: TFTP: Finished system:/its/XMLDefault.cnf.xml, time 00:00:00 for process 203
012108: Jan 20 19:14:22.507 GMT: New Skinny socket accepted [2] (7 active)
012109: Jan 20 19:14:22.507 GMT: sin_family 2, sin_port 18230, in_addr 10.0.8.21
012110: Jan 20 19:14:22.507 GMT: skinny_add_socket 2 10.0.8.21 18230
012111: Jan 20 19:14:22.675 GMT: %IPPHONE-6-REG_ALARM: 25: Name=SEP00192F87A7C6 Load= TERM70.DEFAULT Last=Initialized
012112: Jan 20 19:14:22.719 GMT: ephone-(10)[8] StationRegisterMessage (6/7/42) from 10.0.8.21
012113: Jan 20 19:14:22.719 GMT: ephone-(10)[8] Register StationIdentifier DeviceName SEP00192F87A7C6
012114: Jan 20 19:14:22.719 GMT: ephone-(10)[8] StationIdentifier Instance 0  deviceType 30006
012115: Jan 20 19:14:22.719 GMT: ephone-10[1]:stationIpAddr 10.0.8.21
012116: Jan 20 19:14:22.719 GMT: ephone-10[1]:maxStreams 5
012117: Jan 20 19:14:22.719 GMT: ephone-10[1]:protocol Ver 0x85720011
012118: Jan 20 19:14:22.719 GMT: ephone-10[1]:phone-size 4844 dn-size 608
012119: Jan 20 19:14:22.719 GMT: ephone-(10) Allow any Skinny Server IP address 10.0.8.1012120: Jan 20 19:14:22.719 GMT: ephone-10[1]:Found entry 9 for 00192F87A7C6
012121: Jan 20 19:14:22.719 GMT: ephone-10[1]:socket change 1 to 8
012122: Jan 20 19:14:22.719 GMT: ephone-10[1]:DisAssociate: Closed socket 1 for unregistered phone
012123: Jan 20 19:14:22.719 GMT: ephone-10[-1]:FAILED: CLOSED old socket -1
012124: Jan 20 19:14:22.719 GMT: ephone-10[8]:phone SEP00192F87A7C6 re-associate OK on socket [8]
012125: Jan 20 19:14:22.719 GMT: %IPPHONE-10-REGISTER_NEW: ephone-10:SEP00192F87A7C6 IP:10.0.8.21 Socket:8 DeviceType:Phone has registered.
012126: Jan 20 19:14:22.719 GMT: Phone 9 socket 8
012127: Jan 20 19:14:22.719 GMT: Skinny Local IP address = 10.0.8.1 on port 2000
012128: Jan 20 19:14:22.719 GMT: Skinny Phone IP address = 10.0.8.21 18230
012129: Jan 20 19:14:22.719 GMT: ephone-10[8]:Signal protocol ver 5 to phone with ver 17
012130: Jan 20 19:14:22.719 GMT: ephone-10[8]:Date Format D/M/Y
012131: Jan 20 19:14:22.719 GMT: ephone-10[8]:RegisterAck sent to ephone 8: keepalive period 30 use sccp-version 5
012132: Jan 20 19:14:22.719 GMT: ephone-10[8]:CapabilitiesReq sent
012133: Jan 20 19:14:22.751 GMT: ephone-10[8]:Skinny IP port 3500 set for socket [8]
012134: Jan 20 19:14:22.751 GMT: ephone-10[8]:ButtonTemplateReqMessage
012135: Jan 20 19:14:22.751 GMT: ephone-10[8]:ButtonTemplateReqMessage waiting for Caps
012136: Jan 20 19:14:22.755 GMT: ephone-10[8]:StationSoftKeyTemplateReqMessage
012137: Jan 20 19:14:22.755 GMT: ephone-10[8]:StationSoftKeyTemplateResMessage
012138: Jan 20 19:14:22.755 GMT: ephone-10[8]:StationSoftKeySetReqMessage
012139: Jan 20 19:14:22.755 GMT: ephone-10[8]:Removed SkPark key
012140: Jan 20 19:14:22.755 GMT: ephone-10[8]:StationSoftKeySetResMessage
012141: Jan 20 19:14:22.755 GMT: ephone-10[8]:StationConfigStatReqMessage
012142: Jan 20 19:14:22.755 GMT: ephone-10[8]:StationConfigStatMessage sent for device SEP00192F87A7C6
012143: Jan 20 19:14:22.863 GMT: ephone-10[8]:CapabilitiesRes received
012144: Jan 20 19:14:22.863 GMT: ephone-10[8]:Caps list 8
WideBand_256K 40 ms
G711Ulaw64k 40 ms
G711Alaw64k 40 ms
G729AnnexB 60 ms
G729AnnexAwAnnexB  60 ms
G729  60 ms
G729AnnexA 60 ms
Unrecognized Media Type 257  1 ms


After the Registration, you can verify the Registration status using # show ephone registered command.


LAB-2811-BOT-P2#show ephone registered



ephone-1[0] Mac:001F.CAE7.AE2D TCP socket:[28] activeLine:0 REGISTERED in SCCP ver 12/9
mediaActive:0 offhook:0 ringing:0 reset:0 reset_sent:0 paging 0 debug:0 caps:9
IP:10.0.1.82 50800 7942  keepalive 16839 max_line 2
button 1: dn 11 number 2221 CH1  IDLE        CH2  IDLE     
button 2: dn 44 number 8110 CH1  IDLE        CH2  IDLE        overlay shared
overlay 2: 44(8110) 45(8110) 46(8110) 53(8110) 54(8110)
paging-dn 61
Preferred Codec: g711ulaw



ephone-2[2] Mac:0022.90FD.2E64 TCP socket:[31] activeLine:0 UNREGISTERED
mediaActive:0 offhook:0 ringing:0 reset:0 reset_sent:0 paging 0 debug:0 caps:13
IP:10.0.1.74 1027 7921  keepalive 2357 max_line 6
button 1: dn 65 number 2265 CH1  DOWN        CH2  DOWN     
Preferred Codec: g711ulaw


2. Using the "debug ephone error mac-address <mac_addr>" you get the following information

Error Messages from the Ephone during the Registration with the CallManager and in case of failed Registration. This debug helps during troubleshooting


#debug ephone error mac-address 0023.0433.B15D

EPHONE error debugging is enabled for phone 0023.0433.B15D




lab_UC520#term mon

003628: Feb 13 14:46:28.121: Sending message 0x88931C84 to phone 6, sock 10, SkinnyMessageID = StationConnectionStatisticsReqID
003629: Feb 13 14:46:28.137: Received message from phone 6, sock 10, SkinnyMessageID = StationConnectionStatisticsResID
003630: Feb 13 14:46:28.621: ephone-6[5/10][SEP00230433B15D]:Deferred Ring Clean Up for DN 3 chan 1 ring phone 5
003631: Feb 13 14:46:32.621: ephone-6[5/10][SEP00230433B15D]:Deferred Ring Clean Up for DN 3 chan 1 ring phone 5
003632: Feb 13 14:46:33.121: Sending message 0x88924A84 to phone 6, sock 10, SkinnyMessageID = StationConnectionStatisticsReqID
003633: Feb 13 14:46:33.141: Received message from phone 6, sock 10, SkinnyMessageID = StationConnectionStatisticsResID
003634: Feb 13 14:46:35.473: Received message from phone 6, sock 10, SkinnyMessageID = StationKeepAliveMessageID
003635: Feb 13 14:46:35.473: Sending message 0x87148D3C to phone 6, sock 10, SkinnyMessageID = StationKeepAliveAckMessageID
003636: Feb 13 14:46:36.121: ephone-6[5/10][SEP00230433B15D]:CallPrompt line 0 ref 0:  Cisco Unified CME
003637: Feb 13 14:46:36.125: Sending message 0x87149B20 to phone 6, sock 10, SkinnyMessageID = Unknown ID 0x121
003638: Feb 13 14:46:36.125: Sending message 0x87149BAC to phone 6, sock 10, SkinnyMessageID = Unknown ID 0x121
003639: Feb 13 14:46:36.125: Sending message 0x87146588 to phone 6, sock 10, SkinnyMessageID = StationClearNotifyMessageID
003640: Feb 13 14:46:36.125: Sending message 0x88924A84 to phone 6, sock 10, SkinnyMessageID = StationDisplayPromptStatusV2MessageID
003641: Feb 13 14:46:36.621: ephone-6[5/10][SEP00230433B15D]:Deferred Ring Clean Up for DN 3 chan 1 ring phone 5
003642: Feb 13 14:46:38.121: Sending message 0x8892D284 to phone 6, sock 10, SkinnyMessageID = StationConnectionStatisticsReqID
003643: Feb 13 14:46:38.141: Received message from phone 6, sock 10, SkinnyMessageID = StationConnectionStatisticsResID
003644: Feb 13 14:46:40.621: ephone-6[5/10][SEP00230433B15D]:Deferred Ring Clean Up for DN 3 chan 1 ring phone 5
003645: Feb 13 14:46:43.121: Sending message 0x8892D284 to phone 6, sock 10, SkinnyMessageID = StationConnectionStatisticsReqID
003646: Feb 13 14:46:43.141: Received message from phone 6, sock 10, SkinnyMessageID = StationConnectionStatisticsResID
003647: Feb 13 14:46:44.621: ephone-6[5/10][SEP00230433B15D]:Deferred Ring Clean Up for DN 3 chan 1 ring phone 5
003648: Feb 13 14:46:48.121: Sending message 0x8892D284 to phone 6, sock 10, SkinnyMessageID = StationConnectionStatisticsReqID
003649: Feb 13 14:46:48.137: Received message from phone 6, sock 10, SkinnyMessageID = StationConnectionStatisticsResID
003650: Feb 13 14:46:48.621: ephone-6[5/10][SEP00230433B15D]:Deferred Ring Clean Up for DN 3 chan 1 ring phone 5
003651: Feb 13 14:46:52.621: ephone-6[5/10][SEP00230433B15D]:Deferred Ring Clean Up for DN 3 chan 1 ring phone 5
003652: Feb 13 14:46:53.121: Sending message 0x8892D284 to phone 6, sock 10, SkinnyMessageID = StationConnectionStatisticsReqID
003653: Feb 13 14:46:53.137: Received message from phone 6, sock 10, SkinnyMessageID = StationConnectionStatisticsResID
003654: Feb 13 14:46:56.117: Received message from phone 6, sock 10, SkinnyMessageID = StationSoftKeyEventMessageID


3. Using the "debug voip ccapi inout" you get the following information


Using the debug voip ccapi inout command you get the following Call informations in detail, like Calling Number, Called Number,
Incoming Dial-peer, Outgoing Dial-peer, Trunk group lables, ANI (A Number CLI), ANI type, NPI, Presentation and also the CAUSE VALUE.
This Cause Value well help you to identify the reason for call drop..



   cc_api_call_setup_ind_common:
   cisco-username=124.7.7.75.34
   ----- ccCallInfo IE subfields -----
  cisco-ani=61293426423
   cisco-anitype=0
   cisco-aniplan=1
   cisco-anipi=0
   cisco-anisi=0
   dest=61245609888
   cisco-desttype=0
   cisco-destplan=1
   cisco-rdie=FFFFFFFF
   cisco-rdn=
   cisco-rdntype=-1
   cisco-rdnplan=-1
   cisco-rdnpi=-1
   cisco-rdnsi=-1
   cisco-redirectreason=-1
*Jan  6 10:05:33.099: //-1/022A14000FDA/CCAPI/cc_api_call_setup_ind_common:
   Interface=0x651A6D88, Call Info(
  Calling Number=61293426423(TON=Unknown, NPI=ISDN, Screening=Not Screened, Presentation=Allowed),
   Called Number=61245609888(TON=Unknown, NPI=ISDN),
   Calling Translated=FALSE, Subscriber Type Str=Unknown, FinalDestinationFlag=TRUE,
  Incoming Dial-peer=100, Progress Indication=NULL(0), Calling IE Present=TRUE,
   Source Trkgrp Route Label=, Target Trkgrp Route Label=, CLID Transparent=FALSE), Call Id=82

*Jan  6 10:05:33.099: //87/022A25151D1B/CCAPI/ccCallDisconnect:
   Cause Value=63, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=63)
*Jan  6 10:05:33.099: //87/022A25151D1B/CCAPI/ccCallDisconnect:
   Cause Value=63, Call Entry(Responsed=TRUE, Cause Value=63)
*Jan  6 10:05:33.099: //87/022A25151D1B/CCAPI/cc_api_get_transfer_info:
   Transfer Number Is Null



4. Using the "debug isdn q931" you get the following information

Using the debug isdn q931 command, you can identify the layer 3 status of the ISDN link established and
gives you the Call status established with the far end operator using ISDN Protocol.
This also give you the Disconnect cause for the call failure. Refer this link for call failure reason.

http://www.cisco.com/en/US/tech/tk801/tk379/technologies_tech_note09186a008012e95f.shtml


20:52:14: ISDN BR0: TX -> SETUP pd = 8 callref = 0x2E 
   20:52:14: Bearer Capability i = 0x8890 
   20:52:14: Channel ID i = 0x83 20:52:14: Keypad Facility i = '5551111' 
   20:52:15: ISDN BR0: RX <- CALL_PROC pd = 8 callref = 0xAE 
   20:52:15: Channel ID i = 0x89

   20:52:16: ISDN BR0: RX <- PROGRESS pd = 8 callref = 0xAE 
   20:52:16: Progress Ind i = 0x8A81 - Call not end-to-end ISDN,
     may have in-band info 
   20:52:16: Signal i = 0x01 - Ring back tone on
   20:52:34: ISDN BR0: RX <- DISCONNECT pd = 8 callref = 0xAE 
   20:52:34: Cause i =0x829F08 - Normal,unspecified or Special intercept,
     call blocked group restriction     
   20:52:34: ISDN BR0: TX -> RELEASE pd = 8 callref = 0x2E 
   20:52:34: ISDN BR0: RX <- RELEASE_COMP pd = 8 callref = 0xAE