Info about Debug Output Running in Voice Gateways

[Muthurani Lavanya Paneerselvam]

Introduction

Purpose of this document is to gain knowledge on the Debugs running in Voice Gateways which will help to do the Troubleshooting

This document is created based on the frequently asked questions related to debugs on 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.No	Debugs
1	debug ephone register <mac-address>"
2	debug ephone error mac-address <mac_addr>
3	debug voip ccapi inout
4	debug 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

Pl rate this document, if it helps. Keep adding your requirements related to debugs under this document in the comment section, document will be updated based on the information required.

Thanks