Examples

The following is output for the debugbackhaul-session-managersessionallcommand:

Router# debug backhaul-session-manager session all 
Router# debug_bsm_command:DEBUG_BSM_SESSION_ALL 
23:49:14:SESSION:XPORT:sig rcvd. session = 34, connid = 0x80BA12FC, sig = 5 (CONN-RESET) 
23:49:14:SESSION:STATE:(34) old-state:OPEN_WAIT, new-state:CLOSE 
23:49:14:SESSION:STATE:(34) state:OPEN_WAIT, use-state:OOS 
23:49:14:SESSION:STATE:(34) old-state:OPEN_WAIT, new-state:OPEN_WAIT 
23:49:14:SESSION:STATE:(34) state:OPEN_WAIT, use-state:OOS 
23:49:19:SESSION:XPORT:sig rcvd. session = 34, connid = 0x80BA12FC, sig = 5 (CONN-RESET) 
23:49:19:SESSION:STATE:(34) old-state:OPEN_WAIT, new-state:CLOSE 
23:49:19:SESSION:STATE:(34) state:OPEN_WAIT, use-state:OOS 
23:49:19:SESSION:STATE:(34) old-state:OPEN_WAIT, new-state:OPEN_WAIT 
23:49:19:SESSION:STATE:(34) state:OPEN_WAIT, use-state:OOS 
23:49:24:SESSION:XPORT:sig rcvd. session = 34, connid = 0x80BA12FC, sig = 5 (CONN-RESET) 
23:49:24:SESSION:STATE:(34) old-state:OPEN_WAIT, new-state:CLOSE 
23:49:24:SESSION:STATE:(34) state:OPEN_WAIT, use-state:OOS 
23:49:24:SESSION:STATE:(34) old-state:OPEN_WAIT, new-state:OPEN_WAIT 
23:49:24:SESSION:STATE:(34) state:OPEN_WAIT, use-state:OOS 
23:49:29:SESSION:XPORT:sig rcvd. session = 34, connid = 0x80BA12FC, sig = 5 (CONN-RESET) 
23:49:29:SESSION:STATE:(34) old-state:OPEN_WAIT, new-state:CLOSE 
23:49:29:SESSION:STATE:(34) state:OPEN_WAIT, use-state:OOS 
23:49:29:SESSION:STATE:(34) old-state:OPEN_WAIT, new-state:OPEN_WAIT 
23:49:29:SESSION:STATE:(34) state:OPEN_WAIT, use-state:OOS 
23:49:34:SESSION:XPORT:sig rcvd. session = 34, connid = 0x80BA12FC, sig = 5 (CONN-RESET) 
23:49:34:SESSION:STATE:(34) old-state:OPEN_WAIT, new-state:CLOSE 
23:49:34:SESSION:STATE:(34) state:OPEN_WAIT, use-state:OOS 
23:49:34:SESSION:STATE:(34) old-state:OPEN_WAIT, new-state:OPEN_WAIT 
23:49:34:SESSION:STATE:(34) state:OPEN_WAIT, use-state:OOS 
23:49:34:SESSION:XPORT:sig rcvd. session = 33, connid = 0x80BA14EC, sig = 1 (CONN-FAILED) 
23:49:34:SESSION:STATE:(33) old-state:OPEN, new-state:CLOSE_WAIT 

The following example displays output for the debugbackhaul-session-managersessionstateall command:

Router# debug backhaul-session-manager session state all 
Router# debug_bsm_command:DEBUG_BSM_SESSION_STATE_ALL 
23:50:54:SESSION:STATE:(34) old-state:OPEN_WAIT, new-state:CLOSE 
23:50:54:SESSION:STATE:(34) state:OPEN_WAIT, use-state:OOS 
23:50:54:SESSION:STATE:(34) old-state:OPEN_WAIT, new-state:OPEN_WAIT 
23:50:54:SESSION:STATE:(34) state:OPEN_WAIT, use-state:OOS 

The following example displays output for the debugbackhaul-session-managersessionxportall command:

Router# debug backhaul-session-manager session xport all Router# debug_bsm_command:DEBUG_BSM_SESSION_XPORT 
23:51:39:SESSION:XPORT:sig rcvd. session = 34, connid = 0x80BA12FC, sig = 5 (CONN-RESET) 
23:51:42:SESSION:XPORT:sig rcvd. session = 33, connid = 0x80BA14EC, sig = 5 (CONN-RESET) 
23:51:44:SESSION:XPORT:sig rcvd. session = 34, connid = 0x80BA12FC, sig = 5 (CONN-RESET) 

Examples

The following is output for the debugbackhaul-session-managersetcommand for all available session sets:

Router# debug backhaul-session-manager set all 
Router# debug_bsm_command:DEBUG_BSM_SET_ALL 
 Function set_proc_event() is called 
Session-Set :test-set 
Old State   :BSM_SET_OOS 
New State   :BSM_SET_OOS 
   Active-Grp  :NONE 
   Session-Grp :g-11 
   Old State   :Group-None 
   New State   :Group-None 
   Event rcvd  :EVT_GRP_INS 
BSM:Event BSM_SET_UP is sent to user 
Session-Set :test-set 
Old State   :BSM_SET_OOS 
New State   :BSM_SET_ACTIVE_IS 
   Active-Grp  :g-11 
   Session-Grp :g-11 
   Old State   :Group-None 
   New State   :Group-Active 
   Event rcvd  :BSM_ACTIVE_TYPE 

The following is output for the debugbackhaul-session-managersetnameset1command:

Router# debug backhaul-session-manager set name set1 
Router# debug_bsm_command:DEBUG_BSM_SET_NAME 
Router# Function set_proc_event() is called 
Session-Set :test-set 
Old State   :BSM_SET_OOS 
New State   :BSM_SET_OOS 
   Active-Grp  :NONE 
   Session-Grp :g-11 
   Old State   :Group-None 
   New State   :Group-None 
   Event rcvd  :EVT_GRP_INS 
Router#BSM:Event BSM_SET_UP is sent to user 
Session-Set :test-set 
Old State   :BSM_SET_OOS 
New State   :BSM_SET_ACTIVE_IS 
   Active-Grp  :g-11 
   Session-Grp :g-11 
   Old State   :Group-None 
   New State   :Group-Active 
   Event rcvd  :BSM_ACTIVE_TYPE 

Examples

The following example shows how to start the debugbackup command:

Router# debug backup

Examples

The following is output from the debugbert command:

Router# debug bert
Bit Error Rate Testing debugging is on
Router# no debug bert
Bit Error Rate Testing debugging is off

Examples

The following example shows output from the debug bfd packet command. The IP address has been specified in order to limit the packet information to one interface:

Router# debug bfd packet 172.16.10.5
BFD packet debugging is on
*Jan 26 14:47:37.645: Tx*IP: dst 172.16.10.1, plen 24. BFD: diag 2, St/D/P/F (1/0/0/0), mult 5, len 24, loc/rem discr 1 1, tx 1000000, rx 1000000 100000, timer 1000 ms, #103
*Jan 26 14:47:37.645: %OSPF-5-ADJCHG: Process 10, Nbr 172.16.10.12 on Ethernet1/4 from FULL to DOWN, Neighbor Down: BFD node down
*Jan 26 14:47:50.685: %OSPF-5-ADJCHG: Process 10, Nbr 172.16.10.12 on Ethernet1/4 from LOADING to FULL, Loading Done
*Jan 26 14:48:00.905: Rx  IP: src 172.16.10.1, plen 24. BFD: diag 0, St/D/P/F (1/0/0/0), mult 4, len 24, loc/rem discr 2 1, tx 1000000, rx 1000000 100000, timer 4000 ms, #50
*Jan 26 14:48:00.905: Tx IP: dst 172.16.10.1, plen 24. BFD: diag 2, St/D/P/F (2/0/0/0), mult 5, len 24, loc/rem discr 1 2, tx 1000000, rx 1000000 100000, timer 1000 ms, #131
*Jan 26 14:48:00.905: Rx  IP: src 172.16.10.1, plen 24. BFD: diag 0, St/D/P/F (3/0/0/0), mult 4, len 24, loc/rem discr 2 1, tx 1000000, rx 1000000 100000, timer 4000 ms, #51
*Jan 26 14:48:00.905: Tx IP: dst 172.16.10.1, plen 24. BFD: diag 0, St/D/P/F (3/0/0/0), mult 5, len 24, loc/rem discr 1 2, tx 1000000, rx 1000000 100000, timer 1000 ms, #132

The following example shows output from the debug bfd event command when an interface between two BFD neighbor routers fails and then comes back online:

Router# debug bfd event
22:53:48: BFD: bfd_neighbor - action:DESTROY, proc:1024, idb:FastEthernet0/1, neighbor:172.16.10.2
22:53:48: BFD: bfd_neighbor - action:DESTROY, proc:512, idb:FastEthernet0/1, neighbor:172.16.10.2
22:53:49: Session [172.16.10.1,172.16.10.2,Fa0/1,1], event DETECT TIMER EXPIRED, state UP -> FAILING
.
.
.
22:56:35: BFD: bfd_neighbor - action:CREATE, proc:1024, idb:FastEthernet0/1, neighbor:172.16.10.2
22:56:37: Session [172.16.10.1,172.16.10.2,Fa0/1,1], event RX IHY 0, state FAILING -> DOWN
22:56:37: Session [172.16.10.1,172.16.10.2,Fa0/1,1], event RX IHY 0, state DOWN -> INIT
22:56:37: Session [172.16.10.1,172.16.10.2,Fa0/1,1], event RX IHY 1, state INIT -> UP

The table below describes the significant fields shown in the display.

The following example shows output from the debug bfd packet command when an interface between two BFD neighbor routers fails and then comes back online. The diagnostic code changes from 0 (No Diagnostic) to 1 (Control Detection Time Expired) because no BFD control packets could be sent (and therefore detected by the BFD peer) after the interface fails. When the interface comes back online, the diagnostic code changes back to 0 to signify that BFD packets can be sent and received by the BFD peers.

Router# debug bfd packet
23:03:25: Rx  IP: src 172.16.10.2, plen 24. BFD: diag 0, H/D/P/F (0/0/0/0), mult 3, len 24, loc/rem discr 5 1, tx 1000000, rx 100007
23:03:25: Tx IP: dst 172.16.10.2, plen 24. BFD: diag 1, H/D/P/F (0/0/0/0), mult 5, len 24, loc/rem discr 1 5, tx 1000000, rx 1000008
23:03:25: Tx IP: dst 172.16.10.2, plen 24. BFD: diag 1, H/D/P/F (1/0/0/0), mult 5, len 24, loc/rem discr 1 5, tx 1000000, rx 1000009

The table below describes the significant fields shown in the display.

Examples

The following is sample output from the debug bgp ipv6 dampeningcommand:

Router# debug bgp ipv6 dampening
00:13:28:BGP(1):charge penalty for 2000:0:0:1::/64 path 2 1 with halflife-time 15 reuse/suppress 750/2000
00:13:28:BGP(1):flapped 1 times since 00:00:00. New penalty is 1000
00:13:28:BGP(1):charge penalty for 2000:0:0:1:1::/80 path 2 1 with halflife-time 15 reuse/suppress 750/2000
00:13:28:BGP(1):flapped 1 times since 00:00:00. New penalty is 1000
00:13:28:BGP(1):charge penalty for 2000:0:0:5::/64 path 2 1 with halflife-time 15 reuse/suppress 750/2000
00:13:28:BGP(1):flapped 1 times since 00:00:00. New penalty is 1000
00:16:03:BGP(1):charge penalty for 2000:0:0:1::/64 path 2 1 with halflife-time 15 reuse/suppress 750/2000
00:16:03:BGP(1):flapped 2 times since 00:02:35. New penalty is 1892
00:18:28:BGP(1):suppress 2000:0:0:1:1::/80 path 2 1 for 00:27:30 (penalty 2671)
00:18:28:halflife-time 15, reuse/suppress 750/2000
00:18:28:BGP(1):suppress 2000:0:0:1::/64 path 2 1 for 00:27:20 (penalty 2664)
00:18:28:halflife-time 15, reuse/suppress 750/2000

The following example shows output for the debug bgp ipv6 dampeningcommand filtered through the prefix list named marketing:

Router# debug bgp ipv6 dampening prefix-list marketing
00:16:08:BGP(1):charge penalty for 2001:0DB8::/64 path 30 with halflife-time 15 
reuse/suppress 750/2000
00:16:08:BGP(1):flapped 1 times since 00:00:00. New penalty is 10

The table below describes the fields shown in the display.

Examples

The following is sample output from the debug bgp ipv6 updatescommand:

Router# debug bgp ipv6 updates
14:04:17:BGP(1):2000:0:0:2::2 computing updates, afi 1, neighbor version 0, table version 1, starting at ::
14:04:17:BGP(1):2000:0:0:2::2 update run completed, afi 1, ran for 0ms, neighbor version 0, start version 1, throttled to 1
14:04:19:BGP(1):sourced route for 2000:0:0:2::1/64 path #0 changed (weight 32768)
14:04:19:BGP(1):2000:0:0:2::1/64 route sourced locally
14:04:19:BGP(1):2000:0:0:2:1::/80 route sourced locally
14:04:19:BGP(1):2000:0:0:3::2/64 route sourced locally
14:04:19:BGP(1):2000:0:0:4::2/64 route sourced locally
14:04:22:BGP(1):2000:0:0:2::2 computing updates, afi 1, neighbor version 1, table version 6, starting at ::
14:04:22:BGP(1):2000:0:0:2::2 send UPDATE (format) 2000:0:0:2::1/64, next 2000:0:0:2::1, metric 0, path 
14:04:22:BGP(1):2000:0:0:2::2 send UPDATE (format) 2000:0:0:2:1::/80, next 2000:0:0:2::1, metric 0, path 
14:04:22:BGP(1):2000:0:0:2::2 send UPDATE (prepend, chgflags:0x208) 2000:0:0:3::2/64, next 2000:0:0:2::1, metric 0, path 
14:04:22:BGP(1):2000:0:0:2::2 send UPDATE (prepend, chgflags:0x208) 2000:0:0:4::2/64, next 2000:0:0:2::1, metric 0, path 

The following is sample output from the debug bgp ipv6 updatescommand filtered through the prefix list named sales:

Router# debug bgp ipv6 updates prefix-list sales
00:18:26:BGP(1):2000:8493:1::2 send UPDATE (prepend, chgflags:0x208) 7878:7878::/64, next 2001:0DB8::36C, metric 0, path 

The table below describes the significant fields shown in the display.

Examples

The following shows how to enable the debug bgp l2vpn vpls updates command:

Device> enable
Device# debug bgp l2vpn vpls updates
BGP updates debugging is on for address family: L2VPN Vpls

Examples

The following example shows output for the debugbgpnsapcommand. The BGP(4) identifies that BGP version 4 is operational.

Router# debug bgp nsap
00:46:46: BGP(4): removing CLNS route to 49.0101
00:46:46: BGP(4): removing CLNS route to 49.0303
00:46:46: BGP(4): removing CLNS route to 49.0404
00:46:46: BGP(4): 10.1.2.1 removing CLNS route 49.0101.1111.1111.1111.1111.00 to
eBGP-neighbor
00:46:46: BGP(4): 10.2.4.4 removing CLNS route 49.0303.4444.4444.4444.4444.00 to
eBGP-neighbor
00:46:59: BGP(4): Applying map to find origin for prefix 49.0202.2222
00:46:59: BGP(4): Applying map to find origin for prefix 49.0202.3333

Examples

The following example shows output for the debugbgpnsapdampeningcommand:

Router# debug bgp nsap dampening
16:21:34: BGP(4): Dampening route-map modified.

Only one line of output is displayed unless thebgpdampening command is configured with a route map in NSAP address family configuration mode. The following example shows output for the debugbgpnsapdampeningcommand when a route map is configured:

20:07:19: BGP(4): charge penalty for 49.0404 path 65202 65404 with halflife-time 15
reuse/suppress 750/2000
20:07:19: BGP(4): flapped 1 times since 00:00:00. New penalty is 1000
20:08:59: BGP(4): charge penalty for 49.0404 path 65202 65404 with halflife-time 15
reuse/suppress 750/2000
20:08:59: BGP(4): flapped 2 times since 00:01:39. New penalty is 1928
20:10:04: BGP(4): charge penalty for 49.0404 path 65202 65404 with halflife-time 15
reuse/suppress 750/2000
20:10:04: BGP(4): flapped 3 times since 00:02:44. New penalty is 2839
20:10:48: BGP(4): suppress 49.0404 path 65202 65404 for 00:28:10 (penalty 2752)
20:10:48: halflife-time 15, reuse/suppress 750/2000

The table below describes the significant fields shown in the display.

Examples

The following example shows output for the debugbgpnsapupdatescommand:

Router# debug bgp nsap updates
02:13:45: BGP(4): 10.0.3.4 send UPDATE (format) 49.0101, next 49.0303.3333.3333.3333.3333.00, metric 0, path 65202 65101
02:13:45: BGP(4): 10.0.3.4 send UPDATE (format) 49.0202, next 49.0303.3333.3333.3333.3333.00, metric 0, path 65202
02:13:45: BGP(4): 10.0.3.4 send UPDATE (format) 49.0303, next 49.0303.3333.3333.3333.3333.00, metric 0, path 
02:13:45: BGP(4): 10.0.2.2 send UPDATE (format) 49.0404, next 49.0303.3333.3333.3333.3333.00, metric 0, path 65404

The table below describes the significant fields shown in the display.

Examples

The following example enables BGP debugging output for IPv6 VPN instances:

Router# debug bgp vpnv6 unicast

Examples

The following is sample output from the debugbri-interface command:

Router# debug bri-interface
BRI: write_sid: wrote 1B for subunit 0, slot 1.
BRI: write_sid: wrote 15 for subunit 0, slot 1.
BRI: write_sid: wrote 17 for subunit 0, slot 1.
BRI: write_sid: wrote 6 for subunit 0, slot 1.
BRI: write_sid: wrote 8 for subunit 0, slot 1.
BRI: write_sid: wrote 11 for subunit 0, slot 1.
BRI: write_sid: wrote 13 for subunit 0, slot 1.
BRI: write_sid: wrote 29 for subunit 0, slot 1.
BRI: write_sid: wrote 1B for subunit 0, slot 1.
BRI: write_sid: wrote 15 for subunit 0, slot 1.
BRI: write_sid: wrote 17 for subunit 0, slot 1.
BRI: write_sid: wrote 20 for subunit 0, slot 1.
BRI: Starting Power Up timer for unit = 0. 
BRI: write_sid: wrote 3 for subunit 0, slot 1.
BRI: Starting T3 timer after expiry of PUP timeout for unit = 0, current state is F4. 
BRI: write_sid: wrote FF for subunit 0, slot 1.
BRI: Activation for unit = 0, current state is F7. 
BRI: enable channel B1 
BRI: write_sid: wrote 14 for subunit 0, slot 1.
%LINK-3-UPDOWN: Interface BRI0: B-Channel 1, changed state to up
%LINK-5-CHANGED: Interface BRI0: B-Channel 1, changed state to up.!!!
BRI: disable channel B1 
BRI: write_sid: wrote 15 for subunit 0, slot 1.
%LINK-3-UPDOWN: Interface BRI0: B-Channel 1, changed state to down
%LINK-5-CHANGED: Interface BRI0: B-Channel 1, changed state to down
%LINEPROTO-5-UPDOWN: Line protocol on Interface BRI0: B-Channel 1, changed state to down

The following line indicates that an internal command was written to the interface controller. The subunit identifies the first interface in the slot.

BRI: write_sid: wrote 1B for subunit 0, slot 1.

The following line indicates that the power-up timer was started for the named unit:

BRI: Starting Power Up timer for unit = 0. 

The following lines indicate that the channel or the protocol on the interface changed state:

%LINK-3-UPDOWN: Interface BRI0: B-Channel 1, changed state to up
%LINK-5-CHANGED: Interface BRI0: B-Channel 1, changed state to up.!!!
%LINEPROTO-5-UPDOWN: Line protocol on Interface BRI0: B-Channel 1, changed state to down

The following line indicates that the channel was disabled:

BRI: disable channel B1 

Lines of output not described are for use by support staff only.

Examples

The following is sample output from the debugbscevent command:

Router# debug bsc event
BSC: Serial2         POLLEE-FSM inp:E_LineFail old_st:CU_Down new_st:TCU_EOFile
BSC: Serial2         POLLEE-FSM inp:E_LineFail old_st:CU_Down new_st:TCU_EOFile
BSC: Serial2         POLLEE-FSM inp:E_LineFail old_st:CU_Down new_st:TCU_EOFile
0:04:32: BSC: Serial2 :SDI-rx: 9 bytes
BSC: Serial2         POLLEE-FSM inp:E_RxEtx old_st:CU_Down new_st:TCU_EOFile
0:04:32: BSC: Serial2 :SDI-rx: 5 bytes
BSC: Serial2         POLLEE-FSM inp:E_RxEnq old_st:CU_Down new_st:TCU_EOFile
BSC: Serial2         POLLEE-FSM inp:E_Timeout old_st:CU_Down new_st:TCU_InFile
BSC: Serial2         POLLEE-FSM inp:E_Timeout old_st:CU_Idle new_st:TCU_InFile
%LINEPROTO-5-UPDOWN: Line protocol on Interface Serial2, changed state to up
%LINK-3-UPDOWN: Interface Serial2, changed state to up
BSC: Serial2         POLLEE-FSM inp:E_Timeout old_st:CU_Idle new_st:TCU_InFile
0:04:35: BSC: Serial2 :SDI-rx: 9 bytes
BSC: Serial2         POLLEE-FSM inp:E_RxEtx old_st:CU_Idle new_st:TCU_InFile
0:04:35: BSC: Serial2 :SDI-rx: 5 bytes
BSC: Serial2         POLLEE-FSM inp:E_RxEnq old_st:CU_Idle new_st:TCU_InFile
0:04:35: BSC: Serial2 :NDI-rx: 3 bytes

Examples

The following is sample output from the debugbscpacket command:

Router# debug bsc packet
 
0:23:33: BSC: Serial2     :NDI-rx : 27 bytes 401A400227F5C31140C11D60C8C5D3D3D51D4013
0:23:33: BSC: Serial2     :SDI-tx : 12 bytes 00323237FF3232606040402D
0:23:33: BSC: Serial2     :SDI-rx : 2 bytes 1070
0:23:33: BSC: Serial2     :SDI-tx : 27 bytes 401A400227F5C31140C11D60C8C5D3D3D51D4013
0:23:33: BSC: Serial2     :SDI-rx : 2 bytes 1061
0:23:33: BSC: Serial2     :SDI-tx : 5 bytes 00323237FF

Examples

The following is sample output from the debugbstuneventscommand of keepalive messages working correctly. If the routers are configured correctly, at least one router will show reply messages.

Router# debug bstun events 
BSTUN: Received Version Reply opcode from (all[2])_172.16.12.2/1976 at 1360
BSTUN: Received Version Request opcode from (all[2])_172.16.12.2/1976 at 1379
BSTUN: Received Version Reply opcode from (all[2])_172.16.12.2/1976 at 1390

Note	In a scenario where there is constantly loaded bidirectional traffic, you might not see keepalive messages because they are sent only when the remote end has been silent for the keepalive period.

The following is sample output from the debugbstuneventsoutput of an event trace in which the wrong TCP address has been specified for the remote peer. These are non-keepalive related messages.

Router# debug bstun events
BSTUN: Change state for peer (C1[1])172.16.12.22/1976 (closed->opening)
BSTUN: Change state for peer (C1[1])172.16.12.22/1976 (opening->open wait)
%BSTUN-6-OPENING: CONN: opening peer (C1[1])172.16.12.22/1976, 3
BSTUN: tcpd sender in wrong state, dropping packet
BSTUN: tcpd sender in wrong state, dropping packet
BSTUN: tcpd sender in wrong state, dropping packet

Examples

The following is sample output from the debugbstunpacket command:

Router# debug
 bstun packet
BSTUN bsc-local-ack: 0:00:00 Serial2         SDI: Addr: 40 Data: 02C1C1C1C1C1C1C1C1C1
BSTUN bsc-local-ack: 0:00:00 Serial2         SDI: Addr: 40 Data: 02C1C1C1C1C1C1C1C1C1
BSTUN bsc-local-ack: 0:00:06 Serial2         NDI: Addr: 40 Data: 0227F5C31140C11D60C8

Examples

The following is sample output from the debug call-home diagnostic-signature action command:

Device# debug call-home diagnostic-signature action

Jan 29 10:42:22.698 CST: DS-ACT-TRACE: call_home_ds_eem_cmd_run[969], 
cli cmd "show version", expect string "", max run time 20000
Jan 29 10:42:22.726 CST: DS-ACT-TRACE: call_home_ds_cb_rcmd_lkup[501], cmd "show version" not exist
Jan 29 10:42:22.726 CST: DS-ACT-TRACE: call_home_ds_cb_rcmd_add[518], cli show version
Jan 29 10:42:22.726 CST: DS-ACT-TRACE: ds_action_element_next_get[918], 
CMD "show version" get the next cmd, done type:DONE_NONE
.
.
.

The following is sample output from the debug call-home diagnostic-signature api command:

Device# debug call-home diagnostic-signature api

Jan 29 10:41:24.902 CST: DS-API-TRACE: call_home_all_lock[101], lock callhome and ds mutex
Jan 29 10:41:24.902 CST: DS-API-TRACE: call_home_ds_lock[42], lock call home ds semaphore
Jan 29 10:41:24.902 CST: DS-API-TRACE: call_home_all_unlock[109], unlock callhome and ds mutex
Jan 29 10:41:24.902 CST: DS-API-TRACE: call_home_ds_unlock[52], unlock call home ds semaphore
.
.
.

The following is sample output from the debug call-home diagnostic-signature cli command:

Device# debug call-home diagnostic-signature cli

Jan 29 10:44:31.402 CST: DS-CLI-TRACE: call_home_ds_eem_cmd_run[981], the first 100 chars of output cmd: show version
Cisco IOS Software, C1861 Software (C1861-ADVENTERPRISEK9-M), Experimental Version 15.
Jan 29 10:44:31.442 CST: DS-CLI-TRACE: call_home_ds_eem_cmd_run[981], the first 100 chars of output cmd: show logging
Syslog logging: enabled (0 messages dropped, 3 messages rate-limited, 0 flushes, 0 over
.
.
.

The following is sample output from the debug call-home diagnostic-signature download command:

Device# debug call-home diagnostic-signature download

Jan 29 10:40:11.050 CST: DS-DNLD-TRACE: call_home_ds_update_thread_create[239], Creating a download process
Jan 29 10:40:11.054 CST: DS-DNLD-TRACE: ds_download[119], 
url is "https://tools-stage.cisco.com/its/service/oddce/services/DDCEService", num_of_ds is 1
Jan 29 10:40:11.054 CST: DS-DNLD-TRACE: ds_collect_content_prolog_values[370], Collecting XML content prolog values
Jan 29 10:40:11.054 CST: DS-DNLD-TRACE: ds_collect_content_prolog_values[489], System Name:CH1861-1
Jan 29 10:40:11.054 CST: DS-DNLD-TRACE: ds_collect_content_prolog_values[494], Unable to get SNMP contact string
Jan 29 10:40:11.054 CST: DS-DNLD-TRACE: ds_collect_content_epilog_values[550], Collecting XML content epilog values
Jan 29 10:40:11.054 CST: DS-DNLD-TRACE: ds_collect_request_values[621], Collecting XML DS request values
.
.
.

The following is sample output from the debug call-home diagnostic-signature event-registration command:

Device# debug call-home diagnostic-signature event-registration

Jan 29 10:40:16.734 CST: DS-REG-TRACE: call_home_ds_event_register[658], register event for ds "6030"
Jan 29 10:40:16.734 CST: DS-REG-TRACE: ds_content_event_reg[515], ds "6030"
Jan 29 10:40:16.734 CST: DS-REG-TRACE: ds_event_sig_reg[304], ds "6030", index 0, event number 1
Jan 29 10:40:16.734 CST: DS-REG-TRACE: call_home_ds_esid_reg[323], ds "6030", index 0, T = 41, S = 3FCH
Jan 29 10:40:16.738 CST: DS-REG-TRACE: ds_event_sig_reg[343], ds "6030", register callback to action
.
.
.

The following is sample output from the debug call-home diagnostic-signature parsing command:

Device# debug call-home diagnostic-signature parsing

Jan 29 10:40:16.734 CST: DS-PARSE-TRACE: call_home_ds_signature_verify[387], signature  passed verification
Jan 29 10:40:16.734 CST: DS-REG-TRACE: call_home_ds_update_type_chk[3211], update DS: "6030", update type NEW
Jan 29 10:40:16.734 CST: DS-REG-TRACE: call_home_ds_content_reparse[3108], reparse ds "6030" content
Jan 29 10:40:16.734 CST: DS-PARSE-TRACE: ds_content_var_reparse[2915], reparse ds var in 6030
Jan 29 10:40:16.734 CST: DS-PARSE-TRACE: ds_sys_var_local_queue_init[2860], copy sys var ds_signature_id
Jan 29 10:40:16.734 CST: DS-PARSE-TRACE: ds_sys_var_local_queue_init[2860], copy sys var ds_hostname
.
.
.

Examples

The following is sample output after the debugcall-mgmt command has been enabled:

Router# debug call-mgmt
Call Management debugging is on
Router#
Dec 26 13:57:27.710: msg_to_calls_mgmt: msg type CPM_NEW_CALL_CSM_CONNECT received
Dec 26 13:57:27.714: In actv_c_proc_message,
   access type CPM_INSERT_NEW_CALL,
   call type CPM_ISDN_ANALOG:
     CSM completed connecting a new modem call
.
.
.
Dec 26 13:57:45.906: msg_to_calls_mgmt: msg type CPM_NEW_CALL_ISDN_CONNECT received
Dec 26 13:57:45.906: In actv_c_proc_message,
   access type CPM_INSERT_NEW_CALL,
   call type CPM_ISDN_ANALOG:
     Added a new ISDN analog call to the active-calls list
     CC-Slot#7, DSX1-Ctrlr#17, DS0-Timeslot#1
     Mdm-Slot#1, Mdm-Port#3, TTY#219
.
.
.
Dec 26 13:58:25.682: Call mgmt per minute statistics:
     active list length: 1
     history list length: 3
Dec 26 13:58:25.682:      0 timeslots active at slot 7, ctrlr 1
Dec 26 13:58:25.682:      0 timeslots active at slot 7, ctrlr 2
Dec 26 13:58:25.682:      0 timeslots active at slot 7, ctrlr 3
Dec 26 13:58:25.682:      0 timeslots active at slot 7, ctrlr 4
Dec 26 13:58:25.682:      0 timeslots active at slot 7, ctrlr 5
Dec 26 13:58:25.682:      0 timeslots active at slot 7, ctrlr 6
Dec 26 13:58:25.682:      0 timeslots active at slot 7, ctrlr 7
Dec 26 13:58:25.682:      0 timeslots active at slot 7, ctrlr 8
Dec 26 13:58:25.682:      0 timeslots active at slot 7, ctrlr 9
Dec 26 13:58:25.682:      0 timeslots active at slot 7, ctrlr 10
Dec 26 13:58:25.682:      0 timeslots active at slot 7, ctrlr 11
Dec 26 13:58:25.682:      0 timeslots active at slot 7, ctrlr 12
Dec 26 13:58:25.682:      0 timeslots active at slot 7, ctrlr 13
Dec 26 13:58:25.686:      0 timeslots active at slot 7, ctrlr 14
Dec 26 13:58:25.686:      0 timeslots active at slot 7, ctrlr 15
Dec 26 13:58:25.686:      0 timeslots active at slot 7, ctrlr 16
Dec 26 13:58:25.686:      1 timeslots active at slot 7, ctrlr 17
Dec 26 13:58:25.686:      0 timeslots active at slot 7, ctrlr 18
Dec 26 13:58:25.686:      0 timeslots active at slot 7, ctrlr 19
Dec 26 13:58:25.686:      0 timeslots active at slot 7, ctrlr 20
Dec 26 13:58:25.686:      0 timeslots active at slot 7, ctrlr 21
Dec 26 13:58:25.686:      0 timeslots active at slot 7, ctrlr 22
Dec 26 13:58:25.686:      0 timeslots active at slot 7, ctrlr 23
Dec 26 13:58:25.686:      0 timeslots active at slot 7, ctrlr 24
Dec 26 13:58:25.686:      0 timeslots active at slot 7, ctrlr 25
Dec 26 13:58:25.686:      0 timeslots active at slot 7, ctrlr 26
Dec 26 13:58:25.686:      0 timeslots active at slot 7, ctrlr 27
Dec 26 13:58:25.686:      0 timeslots active at slot 7, ctrlr 28
Router# clear int as1/03
Dec 26 13:58:26.538: msg_to_calls_mgmt: msg type CPM_VOICE_CALL_REJ_NO_MOD_AVAIL received
Dec 26 13:58:26.538: In actv_c_proc_message,
   access type CPM_REMOVE_DISC_CALL,
   call type CPM_ISDN_ANALOG:
     Removed a disconnected ISDN analog call
     CC-Slot#7, DSX1-Ctrlr#17, DS0-Timeslot#1
Dec 26 13:58:26.538:      Mdm-Slot#1, Mdm-Port#3, TTY#219

The table below describes the significant fields shown in the display.

Examples

The following example depicts a call coming in to 10.1.1.4 with codec g729r8. Because there is no cache entry for this destination, a probe is sent and values are inserted into the cache. A lookup is performed again, entry is found, and a fallback decision is made to admit the call.

Router# debug call fallback detail
When cache is empty:
debug call fallback detail:
2d19h:fb_lookup_cache:10.1.1.4, codec:g729r8
2d19h:fb_lookup_cache:No entry found.
2d19h:fb_check:no entry exists, enqueueing probe info... 10.1.1.4, codec:g729r8
2d19h:fb_main:Got FB_APP_INQ event
2d19h:fb_main:Dequeued prob info: 10.1.1.4, codec:g729r8
2d19h:fb_lookup_cache:10.1.1.4, codec:g729r8
2d19h:fb_lookup_cache:No entry found.
2d19h:fb_cache_insert:insert:10.1.1.4, codec:g729r8
2d19h:fb_cache_insert:returning entry:10.1.1.4, codec:g729r8
2d19h:fb_initiate_probe:Creating probe... 10.1.1.4, codec:g729r8
2d19h:fb_initiate_probe:Created and started on probe #13, 10.1.1.4, codec:g729r8
2d19h:fb_lookup_cache:10.1.1.4, codec:g729r8
2d19h:fb_lookup_cache:Found entry.
2d19h:fb_check:returned FB_CHECK_TRUE, 10.1.1.4, codec:g729r8
2d19h:fb_main:calling callback function with:TRUE

The following example depicts a call coming in to 10.1.1.4 with codec g729r8. A lookup is performed, entry is found, and a fallback decision is made to admit the call.

Router# debug call fallback detail
When cache is full:
2d19h:fb_lookup_cache:10.1.1.4, codec:g729r8
2d19h:fb_lookup_cache:Found entry.
2d19h:fb_check:returned FB_CHECK_TRUE, 10.1.1.4, codec:g729r8
2d19h:fb_main:calling callback function with:TRUE

Examples

The following example depicts a call coming in to 10.1.1.4 and codec type g729r8. Because there is no cache entry for this IP address, a g729r8 probe is initiated. The probe consists of 20 packet returns with an average delay of 43 milliseconds. The "jitter out" is jitter from source to destination router and "jitter in" is jitter from destination to source router. The delay, loss, and Calculated Planning Impairment Factor (ICPIF) values following g113_calc_icpif are the instantaneous values, whereas those values following "New smoothed values" are the values after applying the smoothing with weight 65.

Router# debug call fallback probe
2d19h:fb_initiate_probe:Probe payload is 32
2d19h:fb_main:NumOfRTT=20, RTTSum=120, loss=0, delay=43, jitter in=0, jitter out=0-> 10.1.1.4, codec:g729r8
2d19h:g113_calc_icpif(delay (w/codec delay)=43, loss=0, expect_factor=10) Icpif=0
2d19h:fb_main:Probe timer expired, 10.1.1.4, codec:g729r8
2d19h:fb_main:NumOfRTT=20, RTTSum=120, loss=0, delay=43, jitter in=0, jitter out=0-> 10.1.1.4, codec:g729r8
2d19h:g113_calc_icpif(delay (w/codec delay)=43, loss=0, expect_factor=10) Icpif=0
2d19h:fb_main:New smoothed values:inst_weight=65, ICPIF=0, Delay=43, Loss=0 -> 10.1.1.4, codec:g729r8

Examples

The following sample output from the debugcallfilterdetail command shows the detailed activity of the GCFM, which is the internal module that controls the debug filtering.

Router# debug call filter detail
5d18h: gcfm_call_get_hash_address: hashtable index = 345
5d18h: gcfm_call_search_hash:no found
5d18h: gcfm_init_call_record:
5d18h: gcfm_init_percall_matchlist:
5d18h: === list 1: service_state=2, callp's: 0
5d18h: gcfm_call_get_hash_address: hashtable index = 345
5d18h: gcfm_call_enlist: count before this enlist 0 on 624D6000
5d18h: gcfm_call_enlist: tail is empty guid=C2E4C789-214A-11D4-804C-000A8A389BA8
5d18h: gcfm_call_get_hash_address: hashtable index = 345
5d18h: gcfm_call_search_hash: search requested guid=C2E4C789-214A-11D4-804C-000A8A389BA8 vs the entry guid=C2E4C789-214A-11D4-804C-000A8A389BA8
5d18h: gcfm_call_search_hash: found
5d18h: gcfm_update_percall_condlist_context:
5d18h: gcfm_update_percall_condlist_context: check cond = 2
5d18h: gcfm_copy_match_cond:
5d18h: gcfm_update_cond_through_matchlist:
5d18h: gcfm_check_percond_with_matchlist: check match-list 1
5d18h: gcfm_matchlist_percond_check:
5d18h: gcfm_matchlist_percond_check: check cond=2
5d18h: gcfm_matchlist_percond_check: compare 42300 to configured 42300
5d18h: gcfm_check_cond_tel_number: 
5d18h: gcfm_check_cond_tel_number: matched
5d18h: gcfm_matchlist_percond_check: checked result is 1
5d18h: gcfm_is_bitfield_identical:
5d18h: gcfm_update_cond_through_matchlist: service=1, percallmatchlist tag=1,current_status = 1, service_filter=0
5d18h: gcfm_percall_notify_condition: not linked call record

The table below describes the significant fields shown in the display.

Examples

The following sample output from the debugcallfilterinout command shows the incoming and outgoing activity of the GCFM, which is the internal module that controls the debug filtering.

Router# debug call filter inout
5d18h: gcfm_generate_guid:
 component ISDN gets guid 
5d18h: gcfm_percall_register: 
component ISDN 
5d18h: gcfm_percall_register: component ISDN  return selected=0
5d18h: gcfm_percall_notify_condition:
 component ISDN for sync=1 
5d18h: gcfm_percall_notify_condition: component ISDN successfully selected = 0
5d18h: gcfm_check_percall_status:
 component TGRM 
5d18h: gcfm_check_percall_status: component TGRM  return selected=0
5d18h: gcfm_check_percall_status: component TGRM 
5d18h: gcfm_check_percall_status: component TGRM  return selected=0
5d18h: gcfm_percall_register:
 component VTSP 
5d18h: gcfm_percall_register: component VTSP for return selected value 0
5d18h: gcfm_percall_notify_condition: component VTSP for sync=1 
5d18h: gcfm_percall_notify_condition: component VTSP successfully selected = 0
5d18h: gcfm_percall_register: component CCAPI 
5d18h: gcfm_percall_register: component CCAPI for return selected value 0
5d18h: gcfm_check_percall_status: component NUMBER-TRANSLATION 
5d18h: gcfm_check_percall_status: component NUMBER-TRANSLATION  return selected=0
5d18h: gcfm_percall_register: component VOICE-IVR-V2 
5d18h: gcfm_percall_register: component VOICE-IVR-V2 for return selected value 0
5d18h: gcfm_check_percall_status: component NUMBER-TRANSLATION 
5d18h: gcfm_check_percall_status: component NUMBER-TRANSLATION 
5d18h: gcfm_check_percall_status: component DIAL-PEER 
5d18h: gcfm_check_percall_status: component DIAL-PEER  return selected=0
5d18h: gcfm_check_percall_status: component NUMBER-TRANSLATION 
5d18h: gcfm_check_percall_status: component DIAL-PEER 
5d18h: gcfm_check_percall_status: component DIAL-PEER  return selected=0
5d18h: gcfm_check_percall_status: component NUMBER-TRANSLATION 
5d18h: gcfm_check_percall_status: component DIAL-PEER 
5d18h: gcfm_check_percall_status: component DIAL-PEER  return selected=0
5d18h: gcfm_check_percall_status: component NUMBER-TRANSLATION 
5d18h: gcfm_check_percall_status: component DIAL-PEER 
5d18h: gcfm_check_percall_status: component DIAL-PEER  return selected=0
5d18h: gcfm_check_percall_status: component NUMBER-TRANSLATION 
5d18h: gcfm_check_percall_status: component DIAL-PEER 
5d18h: gcfm_check_percall_status: component DIAL-PEER  return selected=0
5d18h: gcfm_check_percall_status: component DIAL-PEER 
5d18h: gcfm_check_percall_status: component NUMBER-TRANSLATION 
5d18h: gcfm_percall_register: component CCAPI 
5d18h: gcfm_percall_register: component CCAPI for return selected value 0
5d18h: gcfm_percall_register: component VOICE-IVR-V2 
5d18h: gcfm_percall_register: component VOICE-IVR-V2 for return selected value 0
5d18h: gcfm_percall_notify_condition: component VOICE-IVR-V2 for sync=1 
5d18h: gcfm_percall_notify_condition: component VOICE-
Router#IVR-V2 successfully selected = 1
5d18h: gcfm_percall_register: component H323 
5d18h: gcfm_percall_register: component H323 for return selected value 1
5d18h: gcfm_check_percall_status: component NUMBER-TRANSLATION 
5d18h: gcfm_check_percall_status: component NUMBER-TRANSLATION  return selected=1
5d18h: gcfm_check_percall_status: component NUMBER-TRANSLATION 
5d18h: gcfm_check_percall_status: component NUMBER-TRANSLATION  return selected=1
5d18h: gcfm_check_percall_status: component NUMBER-TRANSLATION 
5d18h: gcfm_check_percall_status: component NUMBER-TRANSLATION  return selected=1
5d18h: gcfm_check_percall_status: component NUMBER-TRANSLATION 
5d18h: gcfm_check_percall_status: component NUMBER-TRANSLATION  return selected=1
5d18h: gcfm_clear_condition:
 component VOICE-IVR-V2
5d18h: gcfm_clear_condition: component VOICE-IVR-V2 successfully
5d18h: gcfm_check_percall_status: component NUMBER-TRANSLATION 
5d18h: gcfm_check_percall_status: component NUMBER-TRANSLATION  return selected=0
5d18h: gcfm_percall_deregister: 
component CCAPI
5d18h: gcfm_percall_deregister:  component CCAPI successfully
5d18h: gcfm_percall_deregister: component H323
5d18h: gcfm_percall_deregister:  component H323 successfully
5d18h: gcfm_percall_deregister: component ISDN
5d18h: gcfm_percall_deregister:  component ISDN successfully
5d18h: gcfm_percall_deregister: component VOICE-IVR-V2
5d18h: gcfm_percall_deregister:  component VOICE-IVR-V2 successfully
5d18h: gcfm_check_percall_status: component NUMBER-TRANSLATION 
5d18h: gcfm_check_percall_status: component NUMBER-TRANSLATION  return selected=0
5d18h: gcfm_percall_deregister: component CCAPI
5d18h: gcfm_percall_deregister:  component CCAPI successfully
5d18h: gcfm_percall_deregister: component VTSP
5d18h: gcfm_percall_deregister:  component VTSP successfully
5d18h: gcfm_percall_deregister: component VOICE-IVR-V2
5d18h: gcfm_terminate_track_guid:
 component VOICE-IVR-V2 terminate, success
5d18h: gcfm_percall_deregister:  component VOICE-IVR-V2 successfully

The table below describes the significant fields shown in the display.

Examples

The following example shows a portion of sample output for a call initiating RSVP when using the debugcallrsvp-syncevents command:

00:03:25:  Parameters: localip: 10.19.101.117 :localport: 16660
00:03:25:  Parameters: remoteip: 10.19.101.116 :remoteport: 17568
00:03:25:  QoS Primitive Event for Call id 0x1 : QoS Listen
00:03:25: Lookup to be done on hashkey 0x1 in hash table 0x61FC2498
00:03:25: Hashed entry 0x1 in call table 0x61FC2498
00:03:25: Entry Not found
00:03:25:  Parameters: localip: 10.19.101.117
00:03:25: 				 remoteip: 10.19.101.116
00:03:25:  QoSpcb : 0x61FC34D8 
00:03:25:  Response Status : 0 
Starting timer for call with CallId 0x1 for 10000 secs
00:03:25:  Handling QoS Primitive QoS Listen 
00:03:25:  Establishing RSVP RESV state : rsvp_request_reservation() 
00:03:25:  For streams from 10.19.101.116:17568 to 10.19.101.117:16660
00:03:25:  RSVP Confirmation required 
00:03:25:  QoS Primitive Event for Call id 0x1 : QoS Resv
00:03:25: Lookup to be done on hashkey 0x1 in hash table 0x61FC2498
00:03:25: Hashed entry 0x1 in call table 0x61FC2498
00:03:25:  Initiating RVSP PATH messages to be Sent : reg_invoke_rsvp_advertise_sender() 
00:03:25:  Advertizing for streams to 10.19.101.116:17568 from 10.19.101.117:16660
00:03:25:  RESV notification event received is : 2
00:03:25: Received RESVCONFIRM
00:03:25:  RESV CONFIRM message received from 10.19.101.116 for RESV setup from 10.19.101.117
00:03:25:  RESV event received is : 0
00:03:25:  RESV message received from 10.19.101.116:17568 for streams from 10.19.101.117:16660
00:03:25:  RESERVATIONS ESTABLISHED : CallId: 1								Stop timer and notify Session Protocol of Success (ie. if notification requested)
00:03:25:  Invoking spQoSresvCallback with Success 

Examples

The following example shows a portion of sample output for a call initiating RSVP when using the debugcallrsvp-syncfunc-trace command in conjunction with the debugcallrsvp-synceventscommand:

00:03:41: Entering Function QoS_Listen
00:03:41: Parameters:localip:10.10.101.116 :localport:17568
00:03:41:remoteip:10.10.101.117 :remoteport:0
00:03:41: Entering Function qos_dequeue_event
00:03:41: Entering Function process_queue_event
00:03:41: QoS Primitive Event for Call id 0x2 :QoS Listen
00:03:41: Entering Function get_pcb
00:03:41: Entering Function hash_tbl_lookup
00:03:41:Lookup to be done on hashkey 0x2 in hash table 0x61FAECD8
00:03:41: Entering Function hash_func
00:03:41:Hashed entry 0x2 in call table 0x61FAECD8
00:03:41:Entry Not found
00:03:41: Entering Function qos_dequeue_pcb
00:03:41: Entering Function qos_initialize_pcb
00:03:41: Parameters:localip:10.10.101.116
00:03:41:			remoteip:10.10.101.117
00:03:41: QoSpcb :0x61FAFD18 
00:03:41: Response Status :0 
00:03:41: Entering Function hash_tbl_insert_entry
00:03:41: Entering Function hash_func
00:03:41: Handling QoS Primitive QoS Listen 
00:03:41: Entering Function qos_dequeue_hash_port_entry
00:03:41: Entering Function qos_port_tbl_insert_entry
00:03:41: Entering Function hash_func
00:03:41: Doing RSVP Listen :rsvp_add_ip_listen_api() 

Examples

The following is sample output from the debug call threshold core
 command:
Router# debug call threshold core
RSCCAC Core info debugging is on

The following is sample output from the debugcallthresholddetail command:

Router# debug call threshold detail
All RSCCAC info debugging is on

Examples

Debug actions are performed on calls by call treatment. The following sample output shows that call treatment is turned on:

Router# debug call treatment action
Call treatment action debugging is on 

Examples

The following is sample output from the debugcallback command:

Router# debug callback
 
TTY7 Callback process initiated, user: exec_test dialstring 123456
TTY7 Callback forced wait = 4 seconds
TTY7 Exec Callback Successful - await exec/autoselect pickup
TTY7: Callback in effect

Examples

The following example shows debug messages for the CAPF server.

Router# debug capf-server all
001891: .Jul 21 18:17:07.014: %IPPHONE-6-UNREGISTER_NORMAL: ephone-1:SEP000E325C9A43 IP:10.10.10.194 So
cket:3 DeviceType:Phone has unregistered normally.
001892: .Jul 21 18:17:20.495: New Connection from phone, socket 1
001893: .Jul 21 18:17:20.495: Created New Handshake Process
001894: .Jul 21 18:17:20.499: SSL Handshake Error -6983
001895: .Jul 21 18:17:21.499: SSL Handshake Error -6983
001896: .Jul 21 18:17:22.555: SSL Handshake Successful
001897: .Jul 21 18:17:22.555: ephone_capf_send_auth_req:
001898: .Jul 21 18:17:22.555: ephone_capf_ssl_write: 12 bytes
001899: .Jul 21 18:17:22.711: ephone_capf_ssl_read: Read 35 bytes
001900: .Jul 21 18:17:22.711: ephone_capf_handle_phone_msg: msgtype 2
001901: .Jul 21 18:17:22.711: ephone_capf_process_auth_res_msg: SEP000E325C9A43 AuthMode 2
001902: .Jul 21 18:17:22.711: ephone_capf_send_delete_cert_req_msg: SEP000E325C9A43
001903: .Jul 21 18:17:22.711: ephone_capf_ssl_write: 8 bytes
001904: .Jul 21 18:17:23.891: ephone_capf_ssl_read: Read 12 bytes
001905: .Jul 21 18:17:23.891: ephone_capf_handle_phone_msg: msgtype 14
001906: .Jul 21 18:17:23.891: certificate delete successful for SEP000E325C9A43
001907: .Jul 21 18:17:24.695: ephone_capf_release_session: SEP000E325C9A43
001908: .Jul 21 18:17:24.695: ephone_capf_send_end_session_msg: SEP000E325C9A43
001909: .Jul 21 18:17:24.695: ephone_capf_ssl_write: 12 bytes
001910: .Jul 21 18:17:25.095: %IPPHONE-6-REG_ALARM: 22: Name=SEP000E325C9A43 Load=7.2(2.0) Last=Rese
t-Reset
001911: .Jul 21 18:17:25.099: %IPPHONE-6-REGISTER: ephone-1:SEP000E325C9A43 IP:10.10.10.194 Socket:2 De
viceType:Phone has registered.
001912: .Jul 21 18:18:05.171: %IPPHONE-6-UNREGISTER_NORMAL: ephone-1:SEP000E325C9A43 IP:1.1.1.127 So
cket:2 DeviceType:Phone has unregistered normally.
001913: .Jul 21 18:18:18.288: New Connection from phone, socket 1
001914: .Jul 21 18:18:18.288: Created New Handshake Process
001915: .Jul 21 18:18:18.292: SSL Handshake Error -6983
001916: .Jul 21 18:18:19.292: SSL Handshake Error -6983
001917: .Jul 21 18:18:20.348: SSL Handshake Successful
001918: .Jul 21 18:18:20.348: ephone_capf_send_auth_req:
001919: .Jul 21 18:18:20.348: ephone_capf_ssl_write: 12 bytes^Z
001920: .Jul 21 18:18:20.492: ephone_capf_ssl_read: Read 35 bytes
001921: .Jul 21 18:18:20.492: ephone_capf_handle_phone_msg: msgtype 2
001922: .Jul 21 18:18:20.492: ephone_capf_process_auth_res_msg: SEP000E325C9A43 AuthMode 2
001923: .Jul 21 18:18:20.492: ephone_capf_send_PhKeyGenReq_msg: SEP000E325C9A43 KeySize 1024
001924: .Jul 21 18:18:20.492: ephone_capf_ssl_write: 13 bytes
001925: .Jul 21 18:18:20.540: ephone_capf_ssl_read: Read 8 bytes
001926: .Jul 21 18:18:20.540: ephone_capf_handle_phone_msg: msgtype 17
001927: .Jul 21 18:18:20.540: ephone_capf_process_req_in_progress: SEP000E325C9A43 delay 0sh
001928: .Jul 21 18:18:21.924: %SYS-5-CONFIG_I: Configured from console by user1 on console  

Examples

The following shows an example session to enable debugging CAS and generate troubleshooting output:

Router# show debug
 
Router# debug cas slot 1 port 0
 
CAS debugging is on 
Router# 
debug-cas is on at slot(1) dsx1(0) 
Router# show debug
 
CAS debugging is on

The following example shows output for the first outgoing call:

Router# p 1.1.1.2
Type escape sequence to abort. 
Sending 5, 100-byte ICMP Echos to 1.1.1.2, timeout is 2 seconds:
*Mar 2 00:17:45: dsx1_alloc_cas_channel: channel 0 dsx1_timeslot 
1(0/0): TX SEIZURE (ABCD=0001)(0/0): RX SEIZURE_ACK (ABCD=1101)(0/1): 
RX_IDLE (ABCD=1001)(0/2): RX_IDLE (ABCD=1001)(0/3): RX_IDLE 
(ABCD=1001)(0/4): RX_IDLE (ABCD=1001)(0/5): RX_IDLE (ABCD=1001)(0/6): 
RX_IDLE (ABCD=1001)(0/7): RX_IDLE (ABCD=1001)(0/8): RX_IDLE 
(ABCD=1001)(0/9): RX_IDLE (ABCD=1001)(0/10): RX_IDLE (ABCD=1001)(0/11): 
RX_IDLE (ABCD=1001)(0/12): RX_IDLE (ABCD=1001)(0/13): RX_IDLE 
(ABCD=1001)(0/14): RX_IDLE (ABCD=1001)(0/16): RX_IDLE (ABCD=1001)(0/17): 
RX_IDLE (ABCD=1001)(0/18): RX_IDLE (ABCD=1001)(0/19): RX_IDLE 
(ABCD=1001)(0/20): RX_IDLE (ABCD=1001)(0/21): RX_IDLE 
(ABCD=1001).(0/22): RX_IDLE (ABCD=1001)(0/23): RX_IDLE 
(ABCD=1001)(0/24): RX_IDLE (ABCD=1001)(0/25): RX_IDLE (ABCD=1001)(0/26): 
RX_IDLE (ABCD=1001)(0/27): RX_IDLE (ABCD=1001)(0/28): RX_IDLE 
(ABCD=1001)(0/29): RX_IDLE (ABCD=1001)(0/30): RX_IDLE 
(ABCD=1001)...(0/0): RX ANSWERED (ABCD=0101). 
Success rate is 0 percent (0/5) 
Router# 
*Mar 2 00:18:13.333: %LINK-3-UPDOWN: Interface Async94, changed state to up 
*Mar 2 00:18:13.333: %DIALER-6-BIND: Interface As94 bound to profile Di1 
*Mar 2 00:18:14.577: %LINEPROTO-5-UPDOWN: Line protocol on Interface Async94, changed state to up 
Router# p 1.1.1.2 
Type escape sequence to abort. 
Sending 5, 100-byte ICMP Echos to 1.1.1.2, timeout is 2 seconds: 
!!!!! 
Success rate is 100 percent (5/5), round-trip min/avg/max = 160/180/236 ms

The following example shows that the call is cleared on the router:

Router# clear int dialer 1 
Router#
(0/0): TX IDLE (ABCD=1001)(0/0): RX IDLE (ABCD=1001) 
*Mar 2 00:18:28.617: %LINK-5-CHANGED: Interface Async94, changed state to reset 
*Mar 2 00:18:28.617: %DIALER-6-UNBIND: Interface As94 unbound from profile Di1 
*Mar 2 00:18:29.617: %LINEPROTO-5-UPDOWN: Line protocol on Interface Async94, changed state to down 
et2-c3745-1# 
*Mar 2 00:18:33.617: %LINK-3-UPDOWN: Interface Async94, changed state to down

The following example shows a subsequent outbound CAS call:

Router# p 1.1.1.2 
Type escape sequence to abort. 
Sending 5, 100-byte ICMP Echos to 1.1.1.2, timeout is 2 seconds:
*Mar 2 00:18:40: dsx1_alloc_cas_channel: channel 5 dsx1_timeslot 
6(0/5): TX SEIZURE (ABCD=0001)(0/5): RX SEIZURE_ACK 
(ABCD=1101)....(0/5): RX ANSWERED (ABCD=0101). 
Success rate is 0 percent (0/5) 
Router# 
*Mar 2 00:19:08.841: %LINK-3-UPDOWN: Interface Async93, changed state to up 
*Mar 2 00:19:08.841: %DIALER-6-BIND: Interface As93 bound to profile Di1 
*Mar 2 00:19:10.033: %LINEPROTO-5-UPDOWN: Line protocol on Interface Async93, changed state to up 
Router# p 1.1.1.2 
Type escape sequence to abort. 
Sending 5, 100-byte ICMP Echos to 1.1.1.2, timeout is 2 seconds: 
!!!!! 
Success rate is 100 percent (5/5), round-trip min/avg/max = 160/167/176 
ms

The following example shows the call cleared by the switch:

Router# 
(0/5): TX IDLE (ABCD=1001)(0/5): RX IDLE (ABCD=1001) 
*Mar 2 00:19:26.249: %LINK-5-CHANGED: Interface Async93, changed state to reset 
*Mar 2 00:19:26.249: %DIALER-6-UNBIND: Interface As93 unbound from profile Di1 
*Mar 2 00:19:27.249: %LINEPROTO-5-UPDOWN: Line protocol on Interface Async93, changed state to down 
Router# 
*Mar 2 00:19:31.249: %LINK-3-UPDOWN: Interface Async93, changed state to down

The following example shows an incoming CAS call:

Router# 
(0/0): RX SEIZURE (ABCD=0001) 
*Mar 2 00:22:40: dsx1_alloc_cas_channel: channel 0 dsx1_timeslot 
1(0/0): TX SEIZURE_ACK (ABCD=1101)(0/0): TX ANSWERED (ABCD=0101) 
Router# 
*Mar 2 00:23:06.249: %LINK-3-UPDOWN: Interface Async83, changed state to up 
*Mar 2 00:23:06.249: %DIALER-6-BIND: Interface As83 bound to profile Di1 
*Mar 2 00:23:07.653: %LINEPROTO-5-UPDOWN: Line protocol on Interface Async83, changed state to up

Examples

The following example shows sample output from the debugccaal2sessioncommand for a forced shutdown of a voice port:

Router# debug ccaal2 session
CCAAL2 Session debugging is on
Router# configure terminal
Enter configuration commands, one per line.  End with CNTL/Z.
Router(config)# voice-port 2/0:0
Router(config-voiceport)# shutdown
00:32:45:ccaal2_call_disconnect:peer tag 0
00:32:45:ccaal2_evhandle_call_disconnect:Entered
00:32:45:ccaal2_call_cleanup:freeccb 1, call_disconnected 1
00:32:45:starting incoming timer:Setting accept_incoming to FALSE and 
00:32:45:timer 2:(0x622F6270)starts - delay (70000)
00:32:45:ccaal2_call_cleanup:Generating Call record
00:32:45:cause=81 tcause=81    cause_text=unspecified
00:32:45:ccaal2_call_cleanup:ccb 0x63FF1700, vdbPtr 0x62DFF2E0
        freeccb_flag=1, call_disconnected_flag=1
00:32:45:%LINK-3-UPDOWN:Interface recEive and transMit2/0:0(1),
changed state to Administrative Shutdown

The following example shows sample output from the debugccaal2sessioncommand for a trunk setup on a voice port:

Router# debug ccaal2 session
Router(config-voiceport)# no shutdown
Router(config-voiceport)#
00:35:28:%LINK-3-UPDOWN:Interface recEive and transMit2/0:0(1),
changed state to up
00:35:35:ccaal2_call_setup_request:Entered
00:35:35:ccaal2_evhandle_call_setup_request:Entered
00:35:35:ccaal2_initialize_ccb:preferred_codec set(-1)(0)
00:35:35:ccaal2_evhandle_call_setup_request:preferred_codec
set(5)(40). VAD is 1
00:35:35:ccaal2_call_setup_trunk:subchannel linking
successfulccaal2_receive:xmitFunc is NULL
00:35:35:ccaal2_caps_ind:PeerTag = 49
00:35:35:     codec(preferred) = 1, fax_rate = 2, vad = 2
00:35:35:     cid = 56, config_bitmask = 258, codec_bytes = 40, 
                       signal_type=8
00:35:36:%HTSP-5-UPDOWN:Trunk port(channel) [2/0:0(1)] is up
Router(config-voiceport)#

Examples

The following is sample output from the debugccedpnamed-dburlfiltercommand at the time that a URL request to the untrusted domain www.example.com was made:

Router# debug cce dp named-db urlfilter 
CCE DP Named DB URLF functionality debugging is on
Router#
*Apr 4 10:38:08.043: CCE* FUNC: cce_dp_named_db_urlf_pkt_classify -- Didn't get token
*Apr 4 10:38:08.043: CCE* FUNC: cce_dp_urlf_truncate_url -- Truncating URL upto script before sending to the trend for classification
*Apr  4 10:38:08.043: CCE* FUNC: urlf_trend_find_cache_entry -- The host tree in bucket 1248 is empty
*Apr 4 10:38:08.043: CCE* FUNC: cce_dp_named_db_urlf_pkt_classify -- Didn't find in cache
*Apr 4 10:38:08.051: CCE  FUNC: urlf_trend_store_response -- Host node with given domain
name not found.
*Apr  4 10:38:08.051: CCE  FUNC: urlf_trend_store_response -- Create domain type cache entry.
*Apr  4 10:38:08.051: CCE  FUNC: cache_size_limit_check -- New cache size=73, existing cache size=0, cache size limit=131072000
*Apr  4 10:38:08.051: CCE  FUNC: create_domain_cache_entry -- Domain cache entry 0x65EE0ED0 created.
*Apr  4 10:38:08.051: CCE  FUNC: create_and_insert_domain_cache_entry --
*Apr  4 10:38:08.051: Domain cache entry 0x65EE0ED0 created and inserted into host tree with root=0x65EE0ED0, root left=0x0, root right=0x0; new node left=0x0, new node right=0x0
*Apr  4 10:38:08.051: CCE  FUNC: cce_dp_named_db_urlf_gen_match_token -- pushing match-info token - class 0xC000000E; filter 45; category 21
*Apr  4 10:38:08.051: CCE  FUNC: cce_dp_named_db_urlf_non_pkt_classify -- Class 0x65C5D484 matched
*Apr  4 17:38:08.051: %URLF-4-URL_BLOCKED: Access denied URL 'http://www.example.com/', client 1.0.0.118:3056 server 192.168.0.30:8080
*Apr  4 10:38:08.055: CCE* FUNC: cce_dp_named_db_urlf_pkt_classify -- Didn't get token
*Apr  4 10:38:08.055: CCE  FUNC: cce_dp_named_db_urlf_pkt_classify -- Didn't get token

Examples

The following is sample output from the debugccfrf11session command:

Router# debug ccfrf11 session
INCOMING CALL SETUP (port setup for answer-mode):
*Mar  6 18:04:07.693:ccfrf11_process_timers:scb (0x60EB6040) timer (0x60EB6098) expired
*Mar  6 18:04:07.693:Setting accept_incoming to TRUE
*Mar  6 18:04:11.213:ccfrf11_incoming_request:peer tag 800:callingNumber=+2602100,
        calledNumber=+3622110
*Mar  6 18:04:11.213:ccfrf11_initialize_ccb:preffered_codec set(-1)(0)
*Mar  6 18:04:11.213:ccfrf11_evhandle_incoming_call_setup_request:calling +2602100,
        called +3622110 Incoming Tag 800
*Mar  6 18:04:11.217:ccfrf11_caps_ind:PeerTag = 800
*Mar  6 18:04:11.217:     codec(preferred) = 4, fax_rate = 2, vad = 2
*Mar  6 18:04:11.217:     cid = 30, config_bitmask = 0, codec_bytes = 20, signal_type=2
*Mar  6 18:04:11.217:     required_bandwidth 8192
*Mar  6 18:04:11.217:ccfrf11_caps_ind:Bandwidth reservation of 8192 bytes succeeded.
*Mar  6 18:04:11.221:ccfrf11_evhandle_call_connect:Entered
CALL SETUP (MASTER):
5d22h:ccfrf11_call_setup_request:Entered
5d22h:ccfrf11_evhandle_call_setup_request:Entered
5d22h:ccfrf11_initialize_ccb:preffered_codec set(-1)(0)
5d22h:ccfrf11_evhandle_call_setup_request:preffered_codec set(9)(24)
5d22h:ccfrf11_call_setup_trunk:subchannel linking successful
5d22h:ccfrf11_caps_ind:PeerTag = 810
5d22h:     codec(preferred) = 512, fax_rate = 2, vad = 2
5d22h:     cid = 30, config_bitmask = 1, codec_bytes = 24, signal_type=2
5d22h:     required_bandwidth 6500
5d22h:ccfrf11_caps_ind:Bandwidth reservation of 6500 bytes succeeded.
CALL TEARDOWN:
*Mar  6 18:09:14.805:ccfrf11_call_disconnect:peer tag 0
*Mar  6 18:09:14.805:ccfrf11_evhandle_call_disconnect:Entered
*Mar  6 18:09:14.805:ccfrf11_call_cleanup:freeccb 1, call_disconnected 1
*Mar  6 18:09:14.805:ccfrf11_call_cleanup:Setting accept_incoming to FALSE and starting
        incoming timer
*Mar  6 18:09:14.809:timer 2:(0x60EB6098)starts - delay (70000)
*Mar  6 18:09:14.809:ccfrf11_call_cleanup:Alive timer stopped
*Mar  6 18:09:14.809:timer 1:(0x60F64104) stops
*Mar  6 18:09:14.809:ccfrf11_call_cleanup:Generating Call record
*Mar  6 18:09:14.809:cause=10 tcause=10    cause_text="normal call clearing."
*Mar  6 18:09:14.809:ccfrf11_call_cleanup:Releasing 8192 bytes of reserved bandwidth
*Mar  6 18:09:14.809:ccfrf11_call_cleanup:ccb 0x60F6404C, vdbPtr 0x610DB7A4
        freeccb_flag=1, call_disconnected_flag=1

Examples

Examples

The debugcch323all command and keyword combination provides output for the following keywords: error, h225, h245, nxe, ras, rawmsg, and session. Examples of output for each keyword follow.

Examples

The following is sample output from a typical debugcch323error request on a Cisco 3640 router:

Router# debug cch323 error
cch323_h225_receiver:received msg of unknown type 5

Examples

The following is sample output from a typical debugcch323h225 request on a Cisco 3640 router:

Router# debug cch323 h225
20:59:17:Set new event H225_EVENT_SETUP
20:59:17:H225 FSM:received event H225_EVENT_SETUP while at state H225_IDLE
20:59:17:Changing from H225_IDLE state to H225_SETUP state
20:59:17:cch323_h225_receiver:received msg of type SETUPCFM_CHOSEN
20:59:17:H225 FSM:received event H225_EVENT_SETUP_CFM_IND while at state 
H225_SETUP
20:59:17:Changing from H225_SETUP state to H225_ACTIVE state
20:59:17:Set new event H225_EVENT_H245_SUCCESS
20:59:17:H225 FSM:received event H225_EVENT_H245_SUCCESS while at state 
H225_ACTIVE
20:59:20:Set new event H225_EVENT_RELEASE
20:59:20:H225 FSM:received event H225_EVENT_RELEASE while at state 
H225_ACTIVE
20:59:20:Changing from H225_ACTIVE state to H225_WAIT_FOR_DRQ state
20:59:20:Set new event H225_EVENT_RAS_SUCCESS
20:59:20:H225 FSM:received event H225_EVENT_RAS_SUCCESS while at state 
H225_WAIT_FOR_DRQ
20:59:20:Changing from H225_WAIT_FOR_DRQ state to H225_IDLE state

The table below describes the significant fields shown in the display.

Examples

The following is sample output from a typical debugcch323h245 request on a Cisco 3640 router:

Router# debug cch323 h245
20:58:23:Changing to new event H245_EVENT_MSD
20:58:23:H245 MS FSM:received event H245_EVENT_MSD while at state 
H245_MS_NONE
20:58:23:changing from H245_MS_NONE state to H245_MS_WAIT state
20:58:23:Changing to new event H245_EVENT_CAP
20:58:23:H245 CAP FSM:received event H245_EVENT_CAP while at state 
H245_CAP_NONE
20:58:23:changing from H245_CAP_NONE state to H245_CAP_WAIT state
20:58:23:cch323_h245_receiver:received msg of type 
M_H245_MS_DETERMINE_INDICATION
20:58:23:Changing to new event H245_EVENT_MS_IND
20:58:23:H245 MS FSM:received event H245_EVENT_MS_IND while at state 
H245_MS_WAIT
20:58:23:cch323_h245_receiver:received msg of type 
M_H245_CAP_TRANSFER_INDICATION
20:58:23:Changing to new event H245_EVENT_CAP_IND
20:58:23:H245 CAP FSM:received event H245_EVENT_CAP_IND while at state 
H245_CAP_WAIT
20:58:23:cch323_h245_receiver:received msg of type 
M_H245_MS_DETERMINE_CONFIRM
20:58:23:Changing to new event H245_EVENT_MS_CFM
20:58:23:H245 MS FSM:received event H245_EVENT_MS_CFM while at state 
H245_MS_WAIT
20:58:23:changing from H245_MS_WAIT state to H245_MS_DONE state
0:58:23:cch323_h245_receiver:received msg of type M_H245_CAP_TRANSFER_CONFIRM
20:58:23:Changing to new event H245_EVENT_CAP_CFM
20:58:23:H245 CAP FSM:received event H245_EVENT_CAP_CFM while at state 
H245_CAP_WAIT
20:58:23:changing from H245_CAP_WAIT state to H245_CAP_DONE state
20:58:23:Changing to new event H245_EVENT_OLC
20:58:23:H245 OLC FSM:received event H245_EVENT_OLC while at state
H245_OLC_NONE
20:58:23:changing from H245_OLC_NONE state to H245_OLC_WAIT state
20:58:23:cch323_h245_receiver:received msg of type 
M_H245_UCHAN_ESTABLISH_INDICATION
20:58:23:Changing to new event H245_EVENT_OLC_IND
20:58:23:H245 OLC FSM:received event H245_EVENT_OLC_IND while at state 
H245_OLC_WAIT
20:58:23:cch323_h245_receiver:received msg of type M_H245_UCHAN_ESTAB_ACK
20:58:23:Changing to new event H245_EVENT_OLC_CFM
20:58:23:H245 OLC FSM:received event H245_EVENT_OLC_CFM while at state 
H245_OLC_WAIT
20:58:23:changing from H245_OLC_WAIT state to H245_OLC_DONE state

The table below describes the significant fields shown in the display.

Examples

The following is sample output from a debugcch323nxe request:

Router# debug cch323 nxe
00:15:54:nxe_handle_usrmsg_to_remote:User Message size is 227
00:15:54:nxe_msg_send_possible:Msg put in the active Q for CRV [3, direction flag 0]
00:15:54:nxe_send_msg:H323chan returns bytes sent=241, the actual len=241, to IPaddr 
[0xA4D4A02], Port [2517]
00:15:54:nxe_handle_usrmsg_to_remote:Usr Msg sent for IPaddr [0xA4D4A02], Port [2517], CRV 
[3, direction flag 0]
00:15:54:nxe_parse_msg_from_remote:Msg received from IP [0xA4D4A02], Port [2517]
00:15:54:nxe_parse_msg_from_remote:Value of PDU flags = 0x2
00:15:54:nxe_parse_payload:Transport msg type, Payload flag = 0x0
00:15:54:nxe_receive_ack:Ack received for 1 pdus
00:15:54:nxe_receive_ack:Ack received for seqnum=13 from IPAddr [0xA4D4A02], Port [2517]
00:15:54:nxe_parse_msg_from_remote:Msg received from IP [0xA4D4A02], Port [2517]
00:15:54:nxe_parse_msg_from_remote:Value of PDU flags = 0x3
00:15:54:nxe_parse_payload:Static msg type, Payload flag = 0xA0
00:15:54:nxe_parse_x_static:Rx H225 msg from IPaddr [0xA4D4A02], Port [2517], CRV [3, 
direction flag 0]
00:15:54:nxe_make_ackmsg:NXE ACK Msg made to ack seqnum=14
00:15:54:nxe_send_msg:H323chan returns bytes sent=16, the actual len=16, to IPaddr 
[0xA4D4A02], Port [2517]
00:15:54:nxe_parse_msg_from_remote:Ack sent for Destination IPaddr [0xA4D4A02], Port 
[2517]
00:15:54:nxe_parse_msg_from_remote:Msg received from IP [0xA4D4A02], Port [2517]
00:15:54:nxe_parse_msg_from_remote:Value of PDU flags = 0x3
00:15:54:nxe_parse_payload:Static msg type, Payload flag = 0xA0
00:15:54:nxe_parse_x_static:Rx H225 msg from IPaddr [0xA4D4A02], Port [2517], CRV [3, 
direction flag 0]

Examples

The following is sample output from a typical debugcch323ras request on a Cisco 3640 router:

Router# debug cch323 ras
20:58:49:Changing to new event CCH323_RAS_EVENT_SEND_RRQ
cch323_run_ras_sm:received event CCH323_RAS_EVENT_SEND_RRQ while at CCH323_RAS_STATE_IDLE state
cch323_run_ras_sm:changing to CCH323_RAS_STATE_RRQ state
cch323_ras_receiver:received msg of type RCF_CHOSEN
cch323_run_ras_sm:received event CCH323_RAS_EVENT_RCF while at CCH323_RAS_STATE_RRQ state
cch323_run_ras_sm:changing to CCH323_RAS_STATE_IDLE state
20:58:59:cch323_percall_ras_sm:received event CCH323_RAS_EVENT_NEWCALL while at CCH323_RAS_STATE_IDLE state
20:58:59:cch323_percall_ras_sm:changing to new state CCH323_RAS_STATE_ARQ
cch323_ras_receiver:received msg of type ACF_CHOSEN
20:58:59:cch323_percall_ras_sm:received event CCH323_RAS_EVENT_ACF while at 
CCH323_RAS_STATE_ARQ state
20:58:59:cch323_percall_ras_sm:changing to new state 
CCH323_RAS_STATE_ACTIVE
20:59:02:cch323_percall_ras_sm:received event CCH323_RAS_EVENT_CALLDISC while
at CCH323_RAS_STATE_ACTIVE state
20:59:02:cch323_percall_ras_sm:changing to new state CCH323_RAS_STATE_DRQ
cch323_ras_receiver:received msg of type DCF_CHOSEN
20:59:02:cch323_percall_ras_sm:received event CCH323_RAS_EVENT_DCF while at
CCH323_RAS_STATE_DRQ state
20:59:02:cch323_percall_ras_sm:changing to new state CCH323_RAS_STATE_IDLE
20:59:04:cch323_percall_ras_sm:received event CCH323_RAS_EVENT_IRR while at 
CCH323_RAS_STATE_ACTIVE state
20:59:04:cch323_percall_ras_sm:changing to new state 
CCH323_RAS_STATE_ACTIVE

The table below describes the significant fields shown in the display.

Examples

The following is sample output from a typical debugcch323rawmsg request on a Cisco 3640 router:

Router# debug cch323 rawmsg
00:32:04:cch323_h225_progress_ind:raw message is 4 bytes:1E 02 81 88
00:32:22:cch323_h225_release_ind:raw message is 80 bytes:00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
00:32:22:cch323_h225_release_notify:raw message is 80 bytes:00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

Examples

Following are two examples of output using the debugcch323session command and keyword combination. The first example is for a call setup on an originating gateway. The second example is for a call setup on a terminating gateway.

The following is sample output from a typical debugcch323session request for a call setup on an originating gateway:

Router# debug cch323 session
00:33:49:cch323_call_setup:gw_id=1, callID=16
00:33:49:cch323_get_new_ccb:ccb (0x81D12D2C) is in use
00:33:49:cch323_call_setup:inserted ccb
cch323_get_peer_info:faxrate[21]proto[2]bitmask[10002]t38_inhibit[0]global_fax[0]
00:33:49:Not using Voice Class Codec
00:33:49:cch323_get_peer_info:preffered_codec set to G729IETF with Bytes = 20
00:33:49:cch323_get_peer_info:peer:81FC0D14, peer->voice_peer_tag:12D, ccb:81D12D2C
00:33:49:Call_setup Playout Mode:0,Init 60, Min 40, Max 200
00:33:49:No account/pin number available
00:33:49:cch323_call_setup_normal:for callID 10
00:33:49:timer (0x81D130D4)starts - delay (15000)
00:33:49:cch323_ct_main:SOCK 1 Event 0x1
00:33:49:timer(0x81D130D4) stops
00:33:49:Near-end Pref Codecs = G.729 IETF
00:33:49: generic_open_logical_channel:codec is g729
00:33:49:cch323_generic_open_logical_channel:Filling in qosCapability field to 0
00:33:49:timer (0x81D130D4)starts - delay (15000)
00:33:49:cch323_ct_main:SOCK 1 Event 0x1
00:33:49:cch323_ct_main:SOCK 1 Event 0x1
00:33:49:      [1]towner_data=0x81D13C88, len=105, msgPtr=0x81D07608
00:33:49:cch323_gw_process_read_socket:received msg for H.225
00:33:49:timer(0x81D130D4) stops
00:33:49:timer (0x81D130D4)starts - delay (180000)
00:33:49:Codec:loc(16), rem(16),
Bytes:loc(20), Fwd(20), Rev(20)
00:33:49:cch323_rtp_open_notify:
00:33:50:cch323_ct_main:SOCK 1 Event 0x1
00:33:50:      [1]towner_data=0x81D13C88, len=71, msgPtr=0x81F1F2E0
00:33:50:cch323_gw_process_read_socket:received msg for H.225
00:33:50:cch323_caps_ind:cap_modem_proto:0, cap_modem_codec:0, cap_modem_redundancy:0 payload 100
00:33:50:cch323_caps_ind:Load DSP with Negotiated codec(16) g729r8, Bytes=20
00:33:50:cch323_caps_ind:set DSP for dtmf-relay = CC_CAP_DTMF_RELAY_INBAND_VOICE

The following is sample output from a typical debugcch323session request for a call setup on a terminating gateway:

Router# debug cch323 session
00:23:27:cch323_ct_main:SOCK 0 Event 0x1
00:23:27:cch323_ct_main:SOCK 1 Event 0x1
00:23:27:      [1]towner_data=0x81F9CA9C, len=179, msgPtr=0x81D15C6C
00:23:27:cch323_gw_process_read_socket:received msg for H.225
00:23:27:cch323_h225_receiver CCB not existing already
00:23:27:cch323_get_new_ccb:ccb (0x81F90184) is in use
00:23:27:cch323_h225_receiver Got a new CCB for call id -2115467564
00:23:27:cch323_h225_setup_ind
00:23:27:Not using Voice Class Codec
00:23:27:cch323_set_peer:peer:81FB3228, peer->voice_peer_tag:12C, ccb:81F90184
00:23:27:Near-end Pref Codecs = G.729 IETF
00:23:27:Codec:loc(16), rem(16),
Bytes:loc(20), Fwd(20), Rev(20)
00:23:27:cch323_build_fastStart_cap_response:Retrieved qosCapability of 0
00:23:27:cch323_build_fastStart_cap_response:In Response Filling in qosCapability field
to 0
00:23:27:Not using Voice Class Codec

Examples

The following is sample output from the debugcch323capacity command:

Router# debug cch323 capacity
Call Capacity Information tracing is enabled
5d00h: cch323_process_carrier_update: Registered = 1,Event = 1,Reason = 1 
5d00h: cch323_process_carrier_update: CarrierId = CARRIERA_NEWENGLAND
5d00h: cch323_fill_crm_CallCapacities: Reason = 1, GroupID = CARRIERA_NEWENGLAND
5d00h: Capacity Details:           Maximum Channels in Group:    23
      Max. Voice Calls(In) :     23,     Max. Voice Calls(Out):    23
      Active Voice Calls(In):     5,     Active Voice Calls(Out):    7
      Max. Voice Calls(to GK):   23,     Avail. Voice Calls(to GK):   11

The gatekeeper displays this output when trunk groups are added, deleted, or modified or when circuits in a trunk group are deactivated or activated (similar to ISDN layer 2 down/up).

5d00h: cch323_process_carrier_update: Registered = 1,Event = 1,Reason = 1 
5d00h: cch323_process_carrier_update: CarrierId = CARRIERA_NEWENGLAND

The table below describes the significant fields shown in the display.

The gatekeeper displays this output whenever call capacity information is sent to the gatekeeper.

5d00h: cch323_fill_crm_CallCapacities: Reason = 1, GroupID = CARRIERA_NEWENGLAND
5d00h: Capacity Details:           Maximum Channels in Group:    23
      Max. Voice Calls(In) :     23,     Max. Voice Calls(Out):    23
      Active Voice Calls(In):     5,     Active Voice Calls(Out):    7
      Max. Voice Calls(to GK):   23,     Avail. Voice Calls(to GK):   11

The table below describes the significant fields shown in the display.

Examples

The following is sample output from the debugcch323h225 command:

Router# debug cch323 h225
20:59:17:Set new event H225_EVENT_SETUP
20:59:17:H225 FSM:received event H225_EVENT_SETUP while at state H225_IDLE
20:59:17:Changing from H225_IDLE state to H225_SETUP state
20:59:17:cch323_h225_receiver:received msg of type SETUPCFM_CHOSEN
20:59:17:H225 FSM:received event H225_EVENT_SETUP_CFM_IND while at state 
H225_SETUP
20:59:17:Changing from H225_SETUP state to H225_ACTIVE state
20:59:17:Set new event H225_EVENT_H245_SUCCESS
20:59:17:H225 FSM:received event H225_EVENT_H245_SUCCESS while at state 
H225_ACTIVE
20:59:20:Set new event H225_EVENT_RELEASE
20:59:20:H225 FSM:received event H225_EVENT_RELEASE while at state 
H225_ACTIVE
20:59:20:Changing from H225_ACTIVE state to H225_WAIT_FOR_DRQ state
20:59:20:Set new event H225_EVENT_RAS_SUCCESS
20:59:20:H225 FSM:received event H225_EVENT_RAS_SUCCESS while at state 
H225_WAIT_FOR_DRQ
20:59:20:Changing from H225_WAIT_FOR_DRQ state to H225_IDLE state

Examples

The following is sample output from the debugcch323h245 command:

Router# debug cch323 h245
20:58:23:Changing to new event H245_EVENT_MSD
20:58:23:H245 MS FSM:received event H245_EVENT_MSD while at state 
H245_MS_NONE
20:58:23:changing from H245_MS_NONE state to H245_MS_WAIT state
20:58:23:Changing to new event H245_EVENT_CAP
20:58:23:H245 CAP FSM:received event H245_EVENT_CAP while at state 
H245_CAP_NONE
20:58:23:changing from H245_CAP_NONE state to H245_CAP_WAIT state
20:58:23:cch323_h245_receiver:received msg of type 
M_H245_MS_DETERMINE_INDICATION
20:58:23:Changing to new event H245_EVENT_MS_IND
20:58:23:H245 MS FSM:received event H245_EVENT_MS_IND while at state 
H245_MS_WAIT
20:58:23:cch323_h245_receiver:received msg of type 
M_H245_CAP_TRANSFER_INDICATION
20:58:23:Changing to new event H245_EVENT_CAP_IND
20:58:23:H245 CAP FSM:received event H245_EVENT_CAP_IND while at state 
H245_CAP_WAIT
20:58:23:cch323_h245_receiver:received msg of type 
M_H245_MS_DETERMINE_CONFIRM
20:58:23:Changing to new event H245_EVENT_MS_CFM
20:58:23:H245 MS FSM:received event H245_EVENT_MS_CFM while at state 
H245_MS_WAIT
20:58:23:changing from H245_MS_WAIT state to H245_MS_DONE state
0:58:23:cch323_h245_receiver:received msg of type M_H245_CAP_TRANSFER_CONFIRM
20:58:23:Changing to new event H245_EVENT_CAP_CFM
20:58:23:H245 CAP FSM:received event H245_EVENT_CAP_CFM while at state 
H245_CAP_WAIT
20:58:23:changing from H245_CAP_WAIT state to H245_CAP_DONE state
20:58:23:Changing to new event H245_EVENT_OLC
20:58:23:H245 OLC FSM:received event H245_EVENT_OLC while at state
H245_OLC_NONE
20:58:23:changing from H245_OLC_NONE state to H245_OLC_WAIT state
20:58:23:cch323_h245_receiver:received msg of type 
M_H245_UCHAN_ESTABLISH_INDICATION
20:58:23:Changing to new event H245_EVENT_OLC_IND
20:58:23:H245 OLC FSM:received event H245_EVENT_OLC_IND while at state 
H245_OLC_WAIT
20:58:23:cch323_h245_receiver:received msg of type M_H245_UCHAN_ESTAB_ACK
20:58:23:Changing to new event H245_EVENT_OLC_CFM
20:58:23:H245 OLC FSM:received event H245_EVENT_OLC_CFM while at state 
H245_OLC_WAIT
20:58:23:changing from H245_OLC_WAIT state to H245_OLC_DONE state

Examples

The following is debugging output for a single H.323 call:

Router# debug cch323 preauth
CCH323 preauth tracing is enabled
cch323_is_preauth_reqd is TRUE
Jan 23 18:39:56.393: In cch323_send_preauth_req for preauth_id = -1
Jan 23 18:39:56.393: Entering rpms_proc_print_preauth_req 
Jan 23 18:39:56.393: Request = 0
Jan 23 18:39:56.393: Preauth id = 86514
Jan 23 18:39:56.393: EndPt Type  = 1
Jan 23 18:39:56.393: EndPt = 192.168.81.102
Jan 23 18:39:56.393: Resource Service = 1
Jan 23 18:39:56.393: Call_origin = answer
Jan 23 18:39:56.393: Call_type = voip
Jan 23 18:39:56.393: Calling_num = 2230001
Jan 23 18:39:56.393: Called_num = 1#1130001
Jan 23 18:39:56.393: Protocol  = 0
Jan 23 18:39:56.393: cch323_insert_preauth_tree:Created node with preauth_id = 86514 ,ccb 6852D5BC , node 651F87FC
Jan 23 18:39:56.393:rpms_proc_create_node:Created node with preauth_id = 86514 
Jan 23 18:39:56.393:rpms_proc_send_aaa_req:uid got is 466725
Jan 23 18:39:56.397:rpms_proc_preauth_response:Context is for preauth_id 86514, aaa_uid 466725
Jan 23 18:39:56.397: Entering Function cch323_rpms_proc_callback_func
Jan 23 18:39:56.397:cch323_rpms_proc_callback_func:PREAUTH_SUCCESS for preauth id 86514 aaa_uid 466725 auth_serv 1688218168
Jan 23 18:39:56.397:rpms_proc_preauth_response:Deleting Tree node for preauth id 86514 uid 466725
Jan 23 18:39:56.397:cch323_get_ccb_and_delete_from_preauth_tree:Preauth_id=86514
cch323_get_ccb_and_delete_from_preauth_tree:651F87FC node and 6852D5BC ccb

The table below describes the significant fields shown in the display.

Examples

The following is sample output from the debugcch323preauth command:

Router# debug cch323 preauth
20:58:49:Changing to new event CCH323_RAS_EVENT_SEND_RRQ
cch323_run_ras_sm:received event CCH323_RAS_EVENT_SEND_RRQ while at CCH323_RAS_STATE_IDLE state
cch323_run_ras_sm:changing to CCH323_RAS_STATE_RRQ state
cch323_ras_receiver:received msg of type RCF_CHOSEN
cch323_run_ras_sm:received event CCH323_RAS_EVENT_RCF while at CCH323_RAS_STATE_RRQ state
cch323_run_ras_sm:changing to CCH323_RAS_STATE_IDLE state
20:58:59:cch323_percall_ras_sm:received event CCH323_RAS_EVENT_NEWCALL while at CCH323_RAS_STATE_IDLE state
20:58:59:cch323_percall_ras_sm:changing to new state CCH323_RAS_STATE_ARQ
cch323_ras_receiver:received msg of type ACF_CHOSEN
20:58:59:cch323_percall_ras_sm:received event CCH323_RAS_EVENT_ACF while at 
CCH323_RAS_STATE_ARQ state
20:58:59:cch323_percall_ras_sm:changing to new state 
CCH323_RAS_STATE_ACTIVE
20:59:02:cch323_percall_ras_sm:received event CCH323_RAS_EVENT_CALLDISC while
at CCH323_RAS_STATE_ACTIVE state
20:59:02:cch323_percall_ras_sm:changing to new state CCH323_RAS_STATE_DRQ
cch323_ras_receiver:received msg of type DCF_CHOSEN
20:59:02:cch323_percall_ras_sm:received event CCH323_RAS_EVENT_DCF while at
CCH323_RAS_STATE_DRQ state
20:59:02:cch323_percall_ras_sm:changing to new state CCH323_RAS_STATE_IDLE
20:59:04:cch323_percall_ras_sm:received event CCH323_RAS_EVENT_IRR while at 
CCH323_RAS_STATE_ACTIVE state
20:59:04:cch323_percall_ras_sm:changing to new state 
CCH323_RAS_STATE_ACTIVE

Examples

Examples

The following is sample output of the debugging log for an originating Cisco Unified CallManager Express (Cisco Unified CME) gateway after the debugcch323video command was enabled:

Router# show log
Syslog logging: enabled (11 messages dropped, 487 messages rate-limited,
                0 flushes, 0 overruns, xml disabled, filtering disabled)
    Console logging: disabled
    Monitor logging: level debugging, 0 messages logged, xml disabled,
                     filtering disabled
    Buffer logging: level debugging, 1144 messages logged, xml disabled,
                    filtering disabled
    Logging Exception size (4096 bytes)
    Count and timestamp logging messages: disabled
    Trap logging: level informational, 1084 message lines logged
Log Buffer (6000000 bytes):
Jun 13 09:19:42.006: //103030/C7838B198002/H323/cch323_get_peer_info: Entry
Jun 13 09:19:42.006: //103030/C7838B198002/H323/cch323_get_peer_info: Have peer
Jun 13 09:19:42.006: //103030/C7838B198002/H323/cch323_set_pref_codec_list: First preferred codec(bytes)=16(20)
Jun 13 09:19:42.006: //103030/C7838B198002/H323/cch323_get_peer_info: Flow Mode set to FLOW_THROUGH
Jun 13 09:19:42.006: //103030/C7838B198002/H323/cch323_get_caps_chn_info: No peer leg setup params
Jun 13 09:19:42.006: //103030/C7838B198002/H323/cch323_get_caps_chn_info: Setting CCH323_SS_NTFY_VIDEO_INFO
Jun 13 09:19:42.006: //103030/C7838B198002/H323/cch323_set_h323_control_options_outgoing: h245 sm mode = 8463
Jun 13 09:19:42.006: //103030/C7838B198002/H323/cch323_set_h323_control_options_outgoing: h323_ctl=0x20
Jun 13 09:19:42.010: //103030/C7838B198002/H323/cch323_rotary_validate: No peer_ccb available

Examples

The following is sample output of the debugging log for a terminating Cisco Unified Survivable Remote Site Telephony (Cisco Unified SRST) gateway after the debugcch323video command was enabled:

Router# show log
Syslog logging: enabled (11 messages dropped, 466 messages rate-limited,
                0 flushes, 0 overruns, xml disabled, filtering disabled)
    Console logging: disabled
    Monitor logging: level debugging, 0 messages logged, xml disabled,
                     filtering disabled
    Buffer logging: level debugging, 829 messages logged, xml disabled,
                    filtering disabled
    Logging Exception size (4096 bytes)
    Count and timestamp logging messages: disabled
    Trap logging: level informational, 771 message lines logged
Log Buffer (200000 bytes):
Jun 13 09:19:42.011: //103034/C7838B198002/H323/setup_ind: Receive bearer cap infoXRate 24, rateMult 12
Jun 13 09:19:42.011: //103034/C7838B198002/H323/cch323_set_h245_state_mc_mode_incoming: h245 state m/c mode=0x10F, h323_ctl=0x2F
Jun 13 09:19:42.015: //-1/xxxxxxxxxxxx/H323/cch245_event_handler: callID=103034
Jun 13 09:19:42.019: //-1/xxxxxxxxxxxx/H323/cch245_event_handler: Event CC_EV_H245_SET_MODE: data ptr=0x465D5760
Jun 13 09:19:42.019: //-1/xxxxxxxxxxxx/H323/cch323_set_mode: callID=103034, flow Mode=1 spi_mode=0x6
Jun 13 09:19:42.019: //103034/C7838B198002/H323/cch323_do_call_proceeding: set_mode NOT called yet...saved deferred CALL_PROC
Jun 13 09:19:42.019: //103034/C7838B198002/H323/cch323_h245_connection_sm: state=0, event=0, ccb=4461B518, listen state=0
Jun 13 09:19:42.019: //103034/C7838B198002/H323/cch323_process_set_mode: Setting inbound leg mode flags to 0x10F, flow-mode to FLOW_THROUGH
Jun 13 09:19:42.019: //103034/C7838B198002/H323/cch323_process_set_mode: Sending deferred CALL_PROC
Jun 13 09:19:42.019: //103034/C7838B198002/H323/cch323_do_call_proceeding: set_mode called so we can proceed with CALLPROC
Jun 13 09:19:42.027: //103034/C7838B198002/H323/cch323_h245_connection_sm: state=1, event=2, ccb=4461B518, listen state=1
Jun 13 09:19:42.027: //103034/C7838B198002/H323/cch323_send_cap_request: Setting mode to VIDEO MODE
Jun 13 09:19:42.031: //103034/C7838B198002/H323/cch323_h245_cap_ind: Masks au=0xC data=0x2 uinp=0x32

Examples

The following is sample output from the debugccm-managerevents command:

Router# debug ccm-manager events 
*Feb 28 22:56:05.873: cmapp_mgcpapp_go_down: Setting mgc status to NO_RESPONSE
*Feb 28 22:56:05.873: cmapp_host_fsm: New state DOWN for host 0 (172.20.71.38)
*Feb 28 22:56:05.873: cmapp_mgr_process_ev_active_host_failed: Active host 0 (172.20.71.38) failed
*Feb 28 22:56:05.873: cmapp_mgr_check_hostlist: Active host is 0 (172.20.71.38)
*Feb 28 22:56:05.877: cmapp_mgr_switchover: New actv host will be 1 (172.20.71.44)
*Feb 28 22:56:05.877: cmapp_host_fsm: Processing event GO_STANDBY for host 0 (172.20.71.38) in state DOWN
*Feb 28 22:56:05.877: cmapp_open_new_link: Open link for [0]:172.20.71.38
*Feb 28 22:56:05.877: cmbh_open_tcp_link: Opening TCP link with Rem IP 172.20.71.38, Local IP 172.20.71.19, port 2428
*Feb 28 22:56:05.881: cmapp_open_new_link: Open initiated OK: Host 0 (172.20.71.38), session_id=8186DEE4
*Feb 28 22:56:05.881: cmapp_start_open_link_tmr: Host 0 (172.20.71.38), tmr 0
*Feb 28 22:56:05.881: cmapp_host_fsm: New state STANDBY_OPENING for host 0 (172.20.71.38)
*Feb 28 22:56:05.881: cmapp_host_fsm: Processing event GO_ACTIVE for host 1 (172.20.71.44) in state STANDBY_READY
*Feb 28 22:56:05.885: cmapp_mgr_send_rehome: new addr=172.20.71.44,port=2427
*Feb 28 22:56:05.885: cmapp_host_fsm: New state REGISTERING for host 1 (172.20.71.44)

You can use the debugccm-managerconfig-downloadtone command to verify the parameters assigned to each locale. The following sample output shows the locale name United Kingdom and lists all the dual-tone parameters for that region:

Router# debug ccm-manager config-download tone
00:09:07:
cmapp_prefix_process_tag_tones:
00:09:07: cmapp_process_tag_trkLocaleName: region = United Kingdom
00:09:07: cmapp_process_tag_pulse_ratio: pulse ratio = 40
00:09:07: cmapp_process_tag_dtmf_llevel: low frequency level = 65438
00:09:07: cmapp_process_tag_dtmf_hlevel: high frequency level = 65463
00:09:07: cmapp_process_tag_special_oper: operation = uLaw
00:09:07: cmapp_prefix_process_tag_lpig: 
00:09:07: cmapp_process_tag_fxs: ignore LPIG for fxs
00:09:07: cmapp_process_tag_fxo: ignore LPIG for fxo
00:09:07: cmapp_process_tag_digital: ignore LPIG for digital
00:09:07: cmapp_prefix_process_tag_lpog: 
00:09:07: cmapp_process_tag_fxs: ignore LPOG for fxsBoth ports are in service
00:09:07: cmapp_process_tag_fxo: ignore LPOG for fxo
00:09:07: cmapp_process_tag_digital: ignore LPOG for digital
00:09:07: cmapp_prefix_process_tag_tonetable_info: 
00:09:07: 
cmapp_prefix_process_tag_dualtone: TID=[0:CPTONE_BUSY]
00:09:07: cmapp_process_tag_nf: number of frequencies = 1
00:09:07: cmapp_process_tag_dr: direction = 0
00:09:07: cmapp_process_tag_fof: frequency 1 = 400
00:09:07: cmapp_process_tag_fos: frequency 2 = 0
00:09:07: cmapp_process_tag_fot: frequency 3 = 0
00:09:07: cmapp_process_tag_fo4: frequency 4 = 0
00:09:07: cmapp_prefix_process_tag_aof_level: 
00:09:07: cmapp_process_tag_fxs: amplitude of 1st = -200
00:09:07: cmapp_process_tag_fxo: amplitude of 1st = -200
00:09:07: cmapp_process_tag_digital: amplitude of 1st = -240
00:09:07: cmapp_prefix_process_tag_aos_level: 
00:09:07: cmapp_process_tag_fxs: amplitude of 2nd = 0
00:09:07: cmapp_process_tag_fxo: amplitude of 2nd = 0
00:09:07: cmapp_process_tag_digital: amplitude of 2nd = 0
00:09:07: cmapp_prefix_process_tag_aot_level: 
00:09:07: cmapp_process_tag_fxs: amplitude of 3rd = 0
00:09:07: cmapp_process_tag_fxo: amplitude of 3rd = 0
00:09:07: cmapp_process_tag_digital: amplitude of 3rd = 0
00:09:07: cmapp_prefix_process_tag_ao4_level: 
00:09:07: cmapp_process_tag_fxs: amplitude of 4th = 0
00:09:07: cmapp_process_tag_fxo: amplitude of 4th = 0
00:09:07: cmapp_process_tag_digital: amplitude of 4th = 0
00:09:07: cmapp_process_tag_ontf: frequency 1 on time = 375
00:09:07: cmapp_process_tag_oftf: frequency 1 off time = 375
00:09:07: cmapp_process_tag_onts: frequency 2 on time = 0
00:09:07: cmapp_process_tag_ofts: frequency 2 off time = 0
00:09:07: cmapp_process_tag_ontt: frequency 3 on time = 0
00:09:07: cmapp_process_tag_oftt: frequency 3 off time = 0
00:09:07: cmapp_process_tag_ont4: frequency 4 on time = 0
00:09:07: cmapp_process_tag_oft4: frequency 4 off time = 0
00:09:07: cmapp_process_tag_fof2: frequency 1 cadence 2 = 0
00:09:07: cmapp_process_tag_fos2: frequency 2 cadence 2 = 0
00:09:07: cmapp_process_tag_fof3: frequency 1 cadence 3 = 0
00:09:07: cmapp_process_tag_fos3: frequency 2 cadence 3 = 0
00:09:07: cmapp_process_tag_fof4: frequency 1 cadence 4 = 0
00:09:07: cmapp_process_tag_fos4: frequency 2 cadence 4 = 0
00:09:07: cmapp_process_tag_rct1: cadence 1 repeat count = 0
00:09:07: cmapp_process_tag_rct2: cadence 2 repeat count = 0
00:09:07: cmapp_process_tag_rct3: cadence 3 repeat count = 0
00:09:07: cmapp_process_tag_rct4: cadence 4 repeat count = 0
00:09:07: 
cmapp_prefix_process_tag_dualtone: TID=[1:CPTONE_RING_BACK]
00:09:07: cmapp_process_tag_nf: number of frequencies = 2
00:09:07: cmapp_process_tag_dr: direction = 0
00:09:07: cmapp_process_tag_fof: frequency 1 = 400
00:09:07: cmapp_process_tag_fos: frequency 2 = 450
00:09:07: cmapp_process_tag_fot: frequency 3 = 0
00:09:07: cmapp_process_tag_fo4: frequency 4 = 0
00:09:07: cmapp_prefix_process_tag_aof_level: 
00:09:07: cmapp_process_tag_fxs: amplitude of 1st = -190
00:09:07: cmapp_process_tag_fxo: amplitude of 1st = -190
00:09:07: cmapp_process_tag_digital: amplitude of 1st = -190
00:09:07: cmapp_prefix_process_tag_aos_level: 
00:09:07: cmapp_process_tag_fxs: amplitude of 2nd = -190
00:09:07: cmapp_process_tag_fxo: amplitude of 2nd = -190
00:09:07: cmapp_process_tag_digital: amplitude of 2nd = -190
00:09:07: cmapp_prefix_process_tag_aot_level: 
00:09:07: cmapp_process_tag_fxs: amplitude of 3rd = 0
00:09:07: cmapp_process_tag_fxo: amplitude of 3rd = 0
00:09:07: cmapp_process_tag_digital: amplitude of 3rd = 0
00:09:07: cmapp_prefix_process_tag_ao4_level: 
00:09:07: cmapp_process_tag_fxs: amplitude of 4th = 0
00:09:07: cmapp_process_tag_fxo: amplitude of 4th = 0
00:09:07: cmapp_process_tag_digital: amplitude of 4th = 0
00:09:07: cmapp_process_tag_ontf: frequency 1 on time = 400
00:09:07: cmapp_process_tag_oftf: frequency 1 off time = 200
00:09:07: cmapp_process_tag_onts: frequency 2 on time = 400
00:09:07: cmapp_process_tag_ofts: frequency 2 off time = 2000
00:09:07: cmapp_process_tag_ontt: frequency 3 on time = 0
00:09:07: cmapp_process_tag_oftt: frequency 3 off time = 0
00:09:07: cmapp_process_tag_ont4: frequency 4 on time = 0
00:09:07: cmapp_process_tag_oft4: frequency 4 off time = 0
00:09:07: cmapp_process_tag_fof2: frequency 1 cadence 2 = 0
00:09:07: cmapp_process_tag_fos2: frequency 2 cadence 2 = 0
00:09:07: cmapp_process_tag_fof3: frequency 1 cadence 3 = 0
00:09:07: cmapp_process_tag_fos3: frequency 2 cadence 3 = 0
00:09:07: cmapp_process_tag_fof4: frequency 1 cadence 4 = 0
00:09:07: cmapp_process_tag_fos4: frequency 2 cadence 4 = 0
00:09:07: cmapp_process_tag_rct1: cadence 1 repeat count = 0
00:09:07: cmapp_process_tag_rct2: cadence 2 repeat count = 0
00:09:07: cmapp_process_tag_rct3: cadence 3 repeat count = 0
00:09:07: cmapp_process_tag_rct4: cadence 4 repeat count = 0
00:09:07: 
cmapp_prefix_process_tag_dualtone: TID=[2:CPTONE_CONGESTION]
00:09:07: cmapp_process_tag_nf: number of frequencies = 1
00:09:07: cmapp_process_tag_dr: direction = 0
00:09:07: cmapp_process_tag_fof: frequency 1 = 400
00:09:07: cmapp_process_tag_fos: frequency 2 = 0
00:09:07: cmapp_process_tag_fot: frequency 3 = 0
00:09:07: cmapp_process_tag_fo4: frequency 4 = 0
00:09:07: cmapp_prefix_process_tag_aof_level: 
00:09:07: cmapp_process_tag_fxs: amplitude of 1st = -200
00:09:07: cmapp_process_tag_fxo: amplitude of 1st = -200
00:09:07: cmapp_process_tag_digital: amplitude of 1st = -200
00:09:07: cmapp_prefix_process_tag_aos_level: 
00:09:07: cmapp_process_tag_fxs: amplitude of 2nd = 0
00:09:07: cmapp_process_tag_fxo: amplitude of 2nd = 0
00:09:07: cmapp_process_tag_digital: amplitude of 2nd = 0
00:09:07: cmapp_prefix_process_tag_aot_level: 
00:09:07: cmapp_process_tag_fxs: amplitude of 3rd = 0
00:09:07: cmapp_process_tag_fxo: amplitude of 3rd = 0
00:09:07: cmapp_process_tag_digital: amplitude of 3rd = 0
00:09:07: cmapp_prefix_process_tag_ao4_level: 
00:09:07: cmapp_process_tag_fxs: amplitude of 4th = 0
00:09:07: cmapp_process_tag_fxo: amplitude of 4th = 0
00:09:07: cmapp_process_tag_digital: amplitude of 4th = 0
00:09:07: cmapp_process_tag_ontf: frequency 1 on time = 400
00:09:07: cmapp_process_tag_oftf: frequency 1 off time = 350
00:09:07: cmapp_process_tag_onts: frequency 2 on time = 225
00:09:07: cmapp_process_tag_ofts: frequency 2 off time = 525
00:09:07: cmapp_process_tag_ontt: frequency 3 on time = 0
00:09:07: cmapp_process_tag_oftt: frequency 3 off time = 0
00:09:07: cmapp_process_tag_ont4: frequency 4 on time = 0
00:09:07: cmapp_process_tag_oft4: frequency 4 off time = 0
00:09:07: cmapp_process_tag_fof2: frequency 1 cadence 2 = 0
00:09:07: cmapp_process_tag_fos2: frequency 2 cadence 2 = 0
00:09:07: cmapp_process_tag_fof3: frequency 1 cadence 3 = 0
00:09:07: cmapp_process_tag_fos3: frequency 2 cadence 3 = 0
00:09:07: cmapp_process_tag_fof4: frequency 1 cadence 4 = 0
00:09:07: cmapp_process_tag_fos4: frequency 2 cadence 4 = 0
00:09:07: cmapp_process_tag_rct1: cadence 1 repeat count = 0
00:09:07: cmapp_process_tag_rct2: cadence 2 repeat count = 0
00:09:07: cmapp_process_tag_rct3: cadence 3 repeat count = 0
00:09:07: cmapp_process_tag_rct4: cadence 4 repeat count = 0
! end

The following is sample output from the debugccm-managerconfig-downloadallcommand for an error case in which the configuration file cannot be accessed for a Skinny Client Control Protocol (SCCP) download:

*Jan  9 07:28:33.499: cmapp_xml_process_timer: 
*Jan  9 07:28:33.499: cmapp_xml_find_ep_by_name: Checking for ep_name [*]
*Jan  9 07:28:33.499: cmapp_xml_exec_fsm: Endpoint is [*]
*Jan  9 07:28:33.499: cmapp_xml_exec_fsm: endpoint = * state = CMAPP_XML_FILE_DNLD, event = CMAPP_XML_EVT_FILE_DNLD_TIMER
*Jan  9 07:28:33.499: cmapp_xml_file_retry_timer_expired: state = CMAPP_XML_FILE_DNLD, event = CMAPP_XML_EVT_FILE_DNLD_TIMER
*Jan  9 07:29:14.499: cmapp_xml_tftp_download_file: Unable to read file tftp://10.6.6.31/Router.cisco.com.cnf.xml, rc=-2
*Jan  9 07:29:14.499: cmapp_xml_get_xml_file: Could not read file tftp://10.6.6.31/Router.cisco.com.cnf.xml, len = 0
*Jan  9 07:29:14.499: cmapp_xml_tftp_download_file: Unable to read file tftp:///Router.cisco.com.cnf.xml, rc=-2
*Jan  9 07:29:14.499: cmapp_xml_get_xml_file: Could not read file tftp:///Router.cisco.com.cnf.xml, len = 0
*Jan  9 07:29:14.499: cmapp_xml_tftp_download_file: Unable to read file tftp:///Router.cisco.com.cnf.xml, rc=-2
*Jan  9 07:29:14.499: cmapp_xml_get_xml_file: Could not read file tftp:///Router.cisco.com.cnf.xml, len = 0
*Jan  9 07:29:14.499: cmapp_xml_exec_fsm: New state = CMAPP_XML_FILE_DNLD, ep = 6544CFA8 

The following is sample output from the debugccm-managerconfig-downloadallcommand for a successful SCCP download:

*Jan  9 09:44:45.543: cmapp_sccp_config:
*Jan  9 09:44:45.543: cmapp_sccp_reset_curcfg: 
*Jan  9 09:44:45.543: cmapp_sccp_init_curcfg:
*Jan  9 09:44:45.543: cmapp_sccp_download_gw_config_file:
*Jan  9 09:44:45.543: cmapp_sccp_get_gw_name:
*Jan  9 09:44:45.543: cmapp_sccp_get_gw_name: XML file name generated->SKIGW0C85226910.cnf.xml
*Jan  9 09:44:45.543: cmapp_sccp_get_xml_file_via_tftp:
*Jan  9 09:44:45.543: cmapp_sccp_tftp_download_file:
*Jan  9 09:44:45.543: cmapp_sccp_tftp_get_file_size:
*Jan  9 09:44:45.563: cmapp_sccp_get_buffer:
*Jan  9 09:44:45.575: cmapp_sccp_tftp_download_file: File (tftp://10.2.6.101/SKIGW0C85226910.cnf.xml) read 8162 bytes
*Jan  9 09:44:45.575: cmapp_sccp_get_xml_file_via_tftp: Read file tftp://10.2.6.101/SKIGW0C85226910.cnf.xml, len = 8162
*Jan  9 09:44:45.575: cmapp_parse_gw_xml_file:
*Jan  9 09:44:45.579: cmapp_sccp_gw_chardata_handler: ccm found, priority=0

The following lines show the conversion of XML data into router configuration information for the endpoint:

*Jan  9 09:44:45.579: cmapp_sccp_gw_start_element_handler: Unit has been set to 1
*Jan  9 09:44:45.579: cmapp_sccp_gw_start_element_handler: Subunit has been set to 0
*Jan  9 09:44:45.579: cmapp_sccp_gw_start_element_handler: Endpoint has been set to 0
*Jan  9 09:44:45.579: cmapp_sccp_gw_start_element_handler: Endpoint has been set to 1
*Jan  9 09:44:45.579: cmapp_sccp_gw_start_element_handler: Endpoint has been set to 2
*Jan  9 09:44:45.579: cmapp_sccp_gw_start_element_handler: Endpoint has been set to 3
*Jan  9 09:44:45.579: cmapp_sccp_gw_start_element_handler: Subunit has been set to 1
*Jan  9 09:44:45.579: cmapp_sccp_gw_start_element_handler: Endpoint has been set to 0
*Jan  9 09:44:45.579: cmapp_sccp_gw_start_element_handler: Endpoint has been set to 1
*Jan  9 09:44:45.579: cmapp_sccp_gw_start_element_handler: Unit has been set to 2

The table below describes the significant fields shown in the displays.

Examples

The following example displays debug output from one side of the call:

Router# debug ccsip all
All SIP call tracing enabled
Router1#
*Mar  6 14:10:42: 0x624CFEF8 : State change from (STATE_NONE, SUBSTATE_NONE)  to (STATE_IDLE, SUBSTATE_NONE)
*Mar  6 14:10:42:  Queued event from SIP SPI : SIPSPI_EV_CC_CALL_SETUP
*Mar  6 14:10:42: CCSIP-SPI-CONTROL:  act_idle_call_setup
*Mar  6 14:10:42:  act_idle_call_setup:Not using Voice Class Codec
*Mar  6 14:10:42: act_idle_call_setup: preferred_codec set[0] type :g711ulaw bytes: 160 
*Mar  6 14:10:42:  Queued event from SIP SPI : SIPSPI_EV_CREATE_CONNECTION
*Mar  6 14:10:42: 0x624CFEF8 : State change from (STATE_IDLE, SUBSTATE_NONE)  to (STATE_IDLE, SUBSTATE_CONNECTING)
*Mar  6 14:10:42: REQUEST CONNECTION TO IP:166.34.245.231 PORT:5060
*Mar  6 14:10:42: 0x624CFEF8 : State change from (STATE_IDLE, SUBSTATE_CONNECTING)  to (STATE_IDLE, SUBSTATE_CONNECTING)
*Mar  6 14:10:42: CCSIP-SPI-CONTROL:  act_idle_connection_created
*Mar  6 14:10:42: CCSIP-SPI-CONTROL:  act_idle_connection_created: Connid(1) created to 166.34.245.231:5060, local_port 54113
*Mar  6 14:10:42: sipSPIAddLocalContact
*Mar  6 14:10:42:  Queued event from SIP SPI : SIPSPI_EV_SEND_MESSAGE
*Mar  6 14:10:42: CCSIP-SPI-CONTROL:  sip_stats_method
*Mar  6 14:10:42: 0x624CFEF8 : State change from (STATE_IDLE, SUBSTATE_CONNECTING)  to (STATE_SENT_INVITE, SUBSTATE_NONE)
*Mar  6 14:10:42: Sent: 
INVITE sip:3660210@166.34.245.231;user=phone;phone-context=unknown SIP/2.0
Via: SIP/2.0/UDP  166.34.245.230:54113
From: "3660110" <sip:3660110@166.34.245.230>
To: <sip:3660210@166.34.245.231;user=phone;phone-context=unknown>
Date: Sat, 06 Mar 1993 19:10:42 GMT
Call-ID: ABBAE7AF-823100CE-0-1CCAA69C@172.18.192.194
Cisco-Guid: 2881152943-2184249548-0-483039712
User-Agent: Cisco VoIP Gateway/ IOS 12.x/ SIP enabled
CSeq: 101 INVITE
Max-Forwards: 6
Timestamp: 731427042
Contact: <sip:3660110@166.34.245.230:5060;user=phone>
Expires: 180
Content-Type: application/sdp
Content-Length: 137
v=0
o=CiscoSystemsSIP-GW-UserAgent 1212 283 IN IP4 166.34.245.230
s=SIP Call
t=0 0
c=IN IP4 166.34.245.230
m=audio 20208 RTP/AVP 0
*Mar  6 14:10:42: Received: 
SIP/2.0 100 Trying
Via: SIP/2.0/UDP  166.34.245.230:54113
From: "3660110" <sip:3660110@166.34.245.230>
To: <sip:3660210@166.34.245.231;user=phone;phone-context=unknown>
Date: Mon, 08 Mar 1993 22:36:40 GMT
Call-ID: ABBAE7AF-823100CE-0-1CCAA69C@172.18.192.194
Timestamp: 731427042
Server: Cisco VoIP Gateway/ IOS 12.x/ SIP enabled
CSeq: 101 INVITE
Content-Length: 0
*Mar  6 14:10:42: HandleUdpSocketReads :Msg enqueued for SPI with IPaddr: 166.34.245.231:5060
*Mar  6 14:10:42: CCSIP-SPI-CONTROL:  act_sentinvite_new_message
*Mar  6 14:10:42: CCSIP-SPI-CONTROL:  sipSPICheckResponse
*Mar  6 14:10:42: CCSIP-SPI-CONTROL:  sip_stats_status_code
*Mar  6 14:10:42:  Roundtrip delay 4 milliseconds for method INVITE
*Mar  6 14:10:42: 0x624CFEF8 : State change from (STATE_SENT_INVITE, SUBSTATE_NONE)  to (STATE_RECD_PROCEEDING, SUBSTATE_PROCEEDING_PROCEEDING)
*Mar  6 14:10:42: Received: 
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP  166.34.245.230:54113
From: "3660110" <sip:3660110@166.34.245.230>
To: <sip:3660210@166.34.245.231;user=phone;phone-context=unknown>
Date: Mon, 08 Mar 1993 22:36:40 GMT
Call-ID: ABBAE7AF-823100CE-0-1CCAA69C@172.18.192.194
Timestamp: 731427042
Server: Cisco VoIP Gateway/ IOS 12.x/ SIP enabled
CSeq: 101 INVITE
Content-Type: application/sdp
Content-Length: 137
v=0
o=CiscoSystemsSIP-GW-UserAgent 969 7889 IN IP4 166.34.245.231
s=SIP Call
t=0 0
c=IN IP4 166.34.245.231
m=audio 20038 RTP/AVP 0
*Mar  6 14:10:42: HandleUdpSocketReads :Msg enqueued for SPI with IPaddr: 166.34.245.231:5060
*Mar  6 14:10:42: CCSIP-SPI-CONTROL:  act_recdproc_new_message
*Mar  6 14:10:42: CCSIP-SPI-CONTROL:  sipSPICheckResponse
*Mar  6 14:10:42: CCSIP-SPI-CONTROL:  sipSPICheckResponse : Updating session description
*Mar  6 14:10:42: CCSIP-SPI-CONTROL:  sip_stats_status_code
*Mar  6 14:10:42:  Roundtrip delay 8 milliseconds for method INVITE
*Mar  6 14:10:42: HandleSIP1xxRinging: SDP MediaTypes negotiation successful!
Negotiated Codec      : g711ulaw , bytes :160
Inband Alerting       : 0 
*Mar  6 14:10:42: 0x624CFEF8 : State change from (STATE_RECD_PROCEEDING, SUBSTATE_PROCEEDING_PROCEEDING)  to (STATE_RECD_PROCEEDING, SUBSTATE_PROCEEDING_ALERTING)
*Mar  6 14:10:46: Received: 
SIP/2.0 200 OK
Via: SIP/2.0/UDP  166.34.245.230:54113
From: "3660110" <sip:3660110@166.34.245.230>
To: <sip:3660210@166.34.245.231;user=phone;phone-context=unknown>;tag=27D3FCA8-C7F
Date: Mon, 08 Mar 1993 22:36:40 GMT
Call-ID: ABBAE7AF-823100CE-0-1CCAA69C@172.18.192.194
Timestamp: 731427042
Server: Cisco VoIP Gateway/ IOS 12.x/ SIP enabled
Contact: <sip:3660210@166.34.245.231:5060;user=phone>
CSeq: 101 INVITE
Content-Type: application/sdp
Content-Length: 137
v=0
o=CiscoSystemsSIP-GW-UserAgent 969 7889 IN IP4 166.34.245.231
s=SIP Call
t=0 0
c=IN IP4 166.34.245.231
m=audio 20038 RTP/AVP 0
*Mar  6 14:10:46: HandleUdpSocketReads :Msg enqueued for SPI with IPaddr: 166.34.245.231:5060
*Mar  6 14:10:46: CCSIP-SPI-CONTROL:  act_recdproc_new_message
*Mar  6 14:10:46: CCSIP-SPI-CONTROL:  sipSPICheckResponse
*Mar  6 14:10:46: CCSIP-SPI-CONTROL:  sipSPICheckResponse : Updating session description
*Mar  6 14:10:46: CCSIP-SPI-CONTROL:  sip_stats_status_code
*Mar  6 14:10:46:  Roundtrip delay 3536 milliseconds for method INVITE
*Mar  6 14:10:46: CCSIP-SPI-CONTROL:  act_recdproc_new_message: SDP MediaTypes negotiation successful!
Negotiated Codec      : g711ulaw , bytes :160
*Mar  6 14:10:46: CCSIP-SPI-CONTROL:  sipSPIReconnectConnection
*Mar  6 14:10:46:  Queued event from SIP SPI : SIPSPI_EV_RECONNECT_CONNECTION
*Mar  6 14:10:46: CCSIP-SPI-CONTROL:  recv_200_OK_for_invite
*Mar  6 14:10:46:  Queued event from SIP SPI : SIPSPI_EV_SEND_MESSAGE
*Mar  6 14:10:46: CCSIP-SPI-CONTROL:  sip_stats_method
*Mar  6 14:10:46: 0x624CFEF8 : State change from (STATE_RECD_PROCEEDING, SUBSTATE_PROCEEDING_ALERTING)  to (STATE_ACTIVE, SUBSTATE_NONE)
*Mar  6 14:10:46: The Call Setup Information is :
        Call Control Block (CCB) : 0x624CFEF8
         State of The Call        : STATE_ACTIVE
         TCP Sockets Used         : NO
         Calling Number           : 3660110
         Called Number            : 3660210
         Negotiated Codec         : g711ulaw
         Source IP Address (Media): 166.34.245.230
         Source IP Port    (Media): 20208
         Destn  IP Address (Media): 166.34.245.231
         Destn  IP Port    (Media): 20038
         Destn SIP Addr (Control) : 166.34.245.231
         Destn SIP Port (Control) : 5060
         Destination Name         : 166.34.245.231
*Mar  6 14:10:46: HandleUdpReconnection: Udp socket connected for fd: 1 with 166.34.245.231:5060
*Mar  6 14:10:46: Sent: 
ACK sip:3660210@166.34.245.231:5060;user=phone SIP/2.0
Via: SIP/2.0/UDP  166.34.245.230:54113
From: "3660110" <sip:3660110@166.34.245.230>
To: <sip:3660210@166.34.245.231;user=phone;phone-context=unknown>;tag=27D3FCA8-C7F
Date: Sat, 06 Mar 1993 19:10:42 GMT
Call-ID: ABBAE7AF-823100CE-0-1CCAA69C@172.18.192.194
Max-Forwards: 6
Content-Type: application/sdp
Content-Length: 137
CSeq: 101 ACK
v=0
o=CiscoSystemsSIP-GW-UserAgent 1212 283 IN IP4 166.34.245.230
s=SIP Call
t=0 0
c=IN IP4 166.34.245.230
m=audio 20208 RTP/AVP 0
*Mar  6 14:10:46: CCSIP-SPI-CONTROL:  ccsip_caps_ind
*Mar  6 14:10:46: ccsip_caps_ind: Load DSP with codec (5) g711ulaw, Bytes=160
*Mar  6 14:10:46: ccsip_caps_ind: set DSP for dtmf-relay = CC_CAP_DTMF_RELAY_INBAND_VOICE
*Mar  6 14:10:46: CCSIP-SPI-CONTROL:  ccsip_caps_ack
*Mar  6 14:10:50: Received: 
BYE sip:3660110@166.34.245.230:5060;user=phone SIP/2.0
Via: SIP/2.0/UDP  166.34.245.231:54835
From: <sip:3660210@166.34.245.231;user=phone;phone-context=unknown>;tag=27D3FCA8-C7F
To: "3660110" <sip:3660110@166.34.245.230>
Date: Mon, 08 Mar 1993 22:36:44 GMT
Call-ID: ABBAE7AF-823100CE-0-1CCAA69C@172.18.192.194
User-Agent: Cisco VoIP Gateway/ IOS 12.x/ SIP enabled
Max-Forwards: 6
Timestamp: 731612207
CSeq: 101 BYE
Content-Length: 0
*Mar  6 14:10:50: HandleUdpSocketReads :Msg enqueued for SPI with IPaddr: 166.34.245.231:54835
*Mar  6 14:10:50: CCSIP-SPI-CONTROL:  act_active_new_message
*Mar  6 14:10:50: CCSIP-SPI-CONTROL:  sact_active_new_message_request
*Mar  6 14:10:50: CCSIP-SPI-CONTROL:  sip_stats_method
*Mar  6 14:10:50:  Queued event from SIP SPI : SIPSPI_EV_SEND_MESSAGE
*Mar  6 14:10:50: CCSIP-SPI-CONTROL:  sip_stats_status_code
*Mar  6 14:10:50: CCSIP-SPI-CONTROL:  sipSPIInitiateCallDisconnect : Initiate call disconnect(16) for outgoing call
*Mar  6 14:10:50: 0x624CFEF8 : State change from (STATE_ACTIVE, SUBSTATE_NONE)  to (STATE_DISCONNECTING, SUBSTATE_NONE)
*Mar  6 14:10:50: Sent: 
SIP/2.0 200 OK
Via: SIP/2.0/UDP  166.34.245.231:54835
From: <sip:3660210@166.34.245.231;user=phone;phone-context=unknown>;tag=27D3FCA8-C7F
To: "3660110" <sip:3660110@166.34.245.230>
Date: Sat, 06 Mar 1993 19:10:50 GMT
Call-ID: ABBAE7AF-823100CE-0-1CCAA69C@172.18.192.194
Server: Cisco VoIP Gateway/ IOS 12.x/ SIP enabled
Timestamp: 731612207
Content-Length: 0
CSeq: 101 BYE
*Mar  6 14:10:50:  Queued event From SIP SPI to CCAPI/DNS : SIPSPI_EV_CC_CALL_DISCONNECT
*Mar  6 14:10:50: CCSIP-SPI-CONTROL:  act_disconnecting_disconnect
*Mar  6 14:10:50: CCSIP-SPI-CONTROL:  sipSPICallCleanup
*Mar  6 14:10:50:  Queued event from SIP SPI : SIPSPI_EV_CLOSE_CONNECTION
*Mar  6 14:10:50: CLOSE CONNECTION TO CONNID:1
*Mar  6 14:10:50: sipSPIIcpifUpdate :CallState: 4 Playout: 1755 DiscTime:48305031 ConnTime 48304651
*Mar  6 14:10:50: 0x624CFEF8 : State change from (STATE_DISCONNECTING, SUBSTATE_NONE)  to (STATE_DEAD, SUBSTATE_NONE)
*Mar  6 14:10:50: The Call Setup Information is :
        Call Control Block (CCB) : 0x624CFEF8
         State of The Call        : STATE_DEAD
         TCP Sockets Used         : NO
         Calling Number           : 3660110
         Called Number            : 3660210
         Negotiated Codec         : g711ulaw
         Source IP Address (Media): 166.34.245.230
         Source IP Port    (Media): 20208
         Destn  IP Address (Media): 166.34.245.231
         Destn  IP Port    (Media): 20038
         Destn SIP Addr (Control) : 166.34.245.231
         Destn SIP Port (Control) : 5060
         Destination Name         : 166.34.245.231
*Mar  6 14:10:50: 
        Disconnect Cause (CC)    : 16
        Disconnect Cause (SIP)   : 200
*Mar  6 14:10:50: udpsock_close_connect: Socket fd: 1 closed for connid 1 with remote port: 5060

The following example displays debut output from the other side of the call:

Router# debug ccsip all
All SIP call tracing enabled
3660-2#
*Mar  8 17:36:40: Received: 
INVITE sip:3660210@166.34.245.231;user=phone;phone-context=unknown SIP/2.0
Via: SIP/2.0/UDP  166.34.245.230:54113
From: "3660110" <sip:3660110@166.34.245.230>
To: <sip:3660210@166.34.245.231;user=phone;phone-context=unknown>
Date: Sat, 06 Mar 1993 19:10:42 GMT
Call-ID: ABBAE7AF-823100CE-0-1CCAA69C@172.18.192.194
Cisco-Guid: 2881152943-2184249548-0-483039712
User-Agent: Cisco VoIP Gateway/ IOS 12.x/ SIP enabled
CSeq: 101 INVITE
Max-Forwards: 6
Timestamp: 731427042
Contact: <sip:3660110@166.34.245.230:5060;user=phone>
Expires: 180
Content-Type: application/sdp
Content-Length: 137
v=0
o=CiscoSystemsSIP-GW-UserAgent 1212 283 IN IP4 166.34.245.230
s=SIP Call
t=0 0
c=IN IP4 166.34.245.230
m=audio 20208 RTP/AVP 0
*Mar  8 17:36:40: HandleUdpSocketReads :Msg enqueued for SPI with IPaddr: 166.34.245.230:54113
*Mar  8 17:36:40: CCSIP-SPI-CONTROL:  sipSPISipIncomingCall
*Mar  8 17:36:40: 0x624D8CCC : State change from (STATE_NONE, SUBSTATE_NONE)  to (STATE_IDLE, SUBSTATE_NONE)
*Mar  8 17:36:40: CCSIP-SPI-CONTROL:  act_idle_new_message
*Mar  8 17:36:40: CCSIP-SPI-CONTROL:  sact_idle_new_message_invite
*Mar  8 17:36:40: CCSIP-SPI-CONTROL:  sip_stats_method
*Mar  8 17:36:40:  sact_idle_new_message_invite:Not Using Voice Class Codec
*Mar  8 17:36:40: sact_idle_new_message_invite: Preferred codec[0] type: g711ulaw Bytes :160
*Mar  8 17:36:40: sact_idle_new_message_invite: Media Negotiation successful for an
incoming call
*Mar  8 17:36:40: sact_idle_new_message_invite: Negotiated Codec      : g711ulaw, bytes :160
Preferred Codec       : g711ulaw, bytes :160
*Mar  8 17:36:40:  Queued event from SIP SPI : SIPSPI_EV_SEND_MESSAGE
*Mar  8 17:36:40: CCSIP-SPI-CONTROL:  sip_stats_status_code
*Mar  8 17:36:40: Num of Contact Locations 1 3660110 166.34.245.230 5060
*Mar  8 17:36:40: 0x624D8CCC : State change from (STATE_IDLE, SUBSTATE_NONE)  to (STATE_RECD_INVITE, SUBSTATE_RECD_INVITE_CALL_SETUP)
*Mar  8 17:36:40: Sent: 
SIP/2.0 100 Trying
Via: SIP/2.0/UDP  166.34.245.230:54113
From: "3660110" <sip:3660110@166.34.245.230>
To: <sip:3660210@166.34.245.231;user=phone;phone-context=unknown>
Date: Mon, 08 Mar 1993 22:36:40 GMT
Call-ID: ABBAE7AF-823100CE-0-1CCAA69C@172.18.192.194
Timestamp: 731427042
Server: Cisco VoIP Gateway/ IOS 12.x/ SIP enabled
CSeq: 101 INVITE
Content-Length: 0
*Mar  8 17:36:40:  Queued event From SIP SPI to CCAPI/DNS : SIPSPI_EV_CC_CALL_PROCEEDING
*Mar  8 17:36:40: CCSIP-SPI-CONTROL:  act_recdinvite_proceeding
*Mar  8 17:36:40:  Queued event From SIP SPI to CCAPI/DNS : SIPSPI_EV_CC_CALL_ALERTING
*Mar  8 17:36:40: CCSIP-SPI-CONTROL:  ccsip_caps_ind
*Mar  8 17:36:40: ccsip_caps_ind: codec(negotiated) = 5(Bytes 160)
*Mar  8 17:36:40: ccsip_caps_ind: Load DSP with codec (5) g711ulaw, Bytes=160
*Mar  8 17:36:40: ccsip_caps_ind: set DSP for dtmf-relay = CC_CAP_DTMF_RELAY_INBAND_VOICE
*Mar  8 17:36:40: CCSIP-SPI-CONTROL:  ccsip_caps_ack
*Mar  8 17:36:40: CCSIP-SPI-CONTROL:  act_recdinvite_alerting
*Mar  8 17:36:40:  180 Ringing with SDP - not likely
*Mar  8 17:36:40:  Queued event from SIP SPI : SIPSPI_EV_SEND_MESSAGE
*Mar  8 17:36:40: CCSIP-SPI-CONTROL:  sip_stats_status_code
*Mar  8 17:36:40: 0x624D8CCC : State change from (STATE_RECD_INVITE, SUBSTATE_RECD_INVITE_CALL_SETUP)  to (STATE_SENT_ALERTING, SUBSTATE_NONE)
*Mar  8 17:36:40: Sent: 
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP  166.34.245.230:54113
From: "3660110" <sip:3660110@166.34.245.230>
To: <sip:3660210@166.34.245.231;user=phone;phone-context=unknown>
Date: Mon, 08 Mar 1993 22:36:40 GMT
Call-ID: ABBAE7AF-823100CE-0-1CCAA69C@172.18.192.194
Timestamp: 731427042
Server: Cisco VoIP Gateway/ IOS 12.x/ SIP enabled
CSeq: 101 INVITE
Content-Type: application/sdp
Content-Length: 137
v=0
o=CiscoSystemsSIP-GW-UserAgent 969 7889 IN IP4 166.34.245.231
s=SIP Call
t=0 0
c=IN IP4 166.34.245.231
m=audio 20038 RTP/AVP 0
*Mar  8 17:36:44:  Queued event From SIP SPI to CCAPI/DNS : SIPSPI_EV_CC_CALL_CONNECT
*Mar  8 17:36:44: CCSIP-SPI-CONTROL:  act_sentalert_connect
*Mar  8 17:36:44: sipSPIAddLocalContact
*Mar  8 17:36:44:  Queued event from SIP SPI : SIPSPI_EV_SEND_MESSAGE
*Mar  8 17:36:44: CCSIP-SPI-CONTROL:  sip_stats_status_code
*Mar  8 17:36:44: 0x624D8CCC : State change from (STATE_SENT_ALERTING, SUBSTATE_NONE)  to (STATE_SENT_SUCCESS, SUBSTATE_NONE)
*Mar  8 17:36:44: Sent: 
SIP/2.0 200 OK
Via: SIP/2.0/UDP  166.34.245.230:54113
From: "3660110" <sip:3660110@166.34.245.230>
To: <sip:3660210@166.34.245.231;user=phone;phone-context=unknown>;tag=27D3FCA8-C7F
Date: Mon, 08 Mar 1993 22:36:40 GMT
Call-ID: ABBAE7AF-823100CE-0-1CCAA69C@172.18.192.194
Timestamp: 731427042
Server: Cisco VoIP Gateway/ IOS 12.x/ SIP enabled
Contact: <sip:3660210@166.34.245.231:5060;user=phone>
CSeq: 101 INVITE
Content-Type: application/sdp
Content-Length: 137
v=0
o=CiscoSystemsSIP-GW-UserAgent 969 7889 IN IP4 166.34.245.231
s=SIP Call
t=0 0
c=IN IP4 166.34.245.231
m=audio 20038 RTP/AVP 0
*Mar  8 17:36:44: Received: 
ACK sip:3660210@166.34.245.231:5060;user=phone SIP/2.0
Via: SIP/2.0/UDP  166.34.245.230:54113
From: "3660110" <sip:3660110@166.34.245.230>
To: <sip:3660210@166.34.245.231;user=phone;phone-context=unknown>;tag=27D3FCA8-C7F
Date: Sat, 06 Mar 1993 19:10:42 GMT
Call-ID: ABBAE7AF-823100CE-0-1CCAA69C@172.18.192.194
Max-Forwards: 6
Content-Type: application/sdp
Content-Length: 137
CSeq: 101 ACK
v=0
o=CiscoSystemsSIP-GW-UserAgent 1212 283 IN IP4 166.34.245.230
s=SIP Call
t=0 0
c=IN IP4 166.34.245.230
m=audio 20208 RTP/AVP 0
*Mar  8 17:36:44: HandleUdpSocketReads :Msg enqueued for SPI with IPaddr: 166.34.245.230:54113
*Mar  8 17:36:44: CCSIP-SPI-CONTROL:  act_sentsucc_new_message
*Mar  8 17:36:44: CCSIP-SPI-CONTROL:  sip_stats_method
*Mar  8 17:36:44: 0x624D8CCC : State change from (STATE_SENT_SUCCESS, SUBSTATE_NONE)  to (STATE_ACTIVE, SUBSTATE_NONE)
*Mar  8 17:36:44: The Call Setup Information is :
        Call Control Block (CCB) : 0x624D8CCC
         State of The Call        : STATE_ACTIVE
         TCP Sockets Used         : NO
         Calling Number           : 3660110
         Called Number            : 3660210
         Negotiated Codec         : g711ulaw
         Source IP Address (Media): 166.34.245.231
         Source IP Port    (Media): 20038
         Destn  IP Address (Media): 166.34.245.230
         Destn  IP Port    (Media): 20208
         Destn SIP Addr (Control) : 166.34.245.230
         Destn SIP Port (Control) : 5060
         Destination Name         : 166.34.245.230
*Mar  8 17:36:47:  Queued event From SIP SPI to CCAPI/DNS : SIPSPI_EV_CC_CALL_DISCONNECT
*Mar  8 17:36:47: CCSIP-SPI-CONTROL:  act_active_disconnect
*Mar  8 17:36:47:  Queued event from SIP SPI : SIPSPI_EV_CREATE_CONNECTION
*Mar  8 17:36:47: 0x624D8CCC : State change from (STATE_ACTIVE, SUBSTATE_NONE)  to (STATE_ACTIVE, SUBSTATE_CONNECTING)
*Mar  8 17:36:47: REQUEST CONNECTION TO IP:166.34.245.230 PORT:5060
*Mar  8 17:36:47: 0x624D8CCC : State change from (STATE_ACTIVE, SUBSTATE_CONNECTING)  to (STATE_ACTIVE, SUBSTATE_CONNECTING)
*Mar  8 17:36:47: CCSIP-SPI-CONTROL:  act_active_connection_created
*Mar  8 17:36:47: CCSIP-SPI-CONTROL:  sipSPICheckSocketConnection
*Mar  8 17:36:47: CCSIP-SPI-CONTROL:  sipSPICheckSocketConnection: Connid(1) created to 166.34.245.230:5060, local_port 54835
*Mar  8 17:36:47:  Queued event from SIP SPI : SIPSPI_EV_SEND_MESSAGE
*Mar  8 17:36:47: CCSIP-SPI-CONTROL:  sip_stats_method
*Mar  8 17:36:47: 0x624D8CCC : State change from (STATE_ACTIVE, SUBSTATE_CONNECTING)  to (STATE_DISCONNECTING, SUBSTATE_NONE)
*Mar  8 17:36:47: Sent: 
BYE sip:3660110@166.34.245.230:5060;user=phone SIP/2.0
Via: SIP/2.0/UDP  166.34.245.231:54835
From: <sip:3660210@166.34.245.231;user=phone;phone-context=unknown>;tag=27D3FCA8-C7F
To: "3660110" <sip:3660110@166.34.245.230>
Date: Mon, 08 Mar 1993 22:36:44 GMT
Call-ID: ABBAE7AF-823100CE-0-1CCAA69C@172.18.192.194
User-Agent: Cisco VoIP Gateway/ IOS 12.x/ SIP enabled
Max-Forwards: 6
Timestamp: 731612207
CSeq: 101 BYE
Content-Length: 0
*Mar  8 17:36:47: Received: 
SIP/2.0 200 OK
Via: SIP/2.0/UDP  166.34.245.231:54835
From: <sip:3660210@166.34.245.231;user=phone;phone-context=unknown>;tag=27D3FCA8-C7F
To: "3660110" <sip:3660110@166.34.245.230>
Date: Sat, 06 Mar 1993 19:10:50 GMT
Call-ID: ABBAE7AF-823100CE-0-1CCAA69C@172.18.192.194
Server: Cisco VoIP Gateway/ IOS 12.x/ SIP enabled
Timestamp: 731612207
Content-Length: 0
CSeq: 101 BYE
*Mar  8 17:36:47: HandleUdpSocketReads :Msg enqueued for SPI with IPaddr: 166.34.245.230:54113
*Mar  8 17:36:47: CCSIP-SPI-CONTROL:  act_disconnecting_new_message
*Mar  8 17:36:47: CCSIP-SPI-CONTROL:  sact_disconnecting_new_message_response
*Mar  8 17:36:47: CCSIP-SPI-CONTROL:  sipSPICheckResponse
*Mar  8 17:36:47: CCSIP-SPI-CONTROL:  sip_stats_status_code
*Mar  8 17:36:47:  Roundtrip delay 4 milliseconds for method BYE
*Mar  8 17:36:47: CCSIP-SPI-CONTROL:  sipSPICallCleanup
*Mar  8 17:36:47:  Queued event from SIP SPI : SIPSPI_EV_CLOSE_CONNECTION
*Mar  8 17:36:47: CLOSE CONNECTION TO CONNID:1
*Mar  8 17:36:47: sipSPIIcpifUpdate :CallState: 4 Playout: 1265 DiscTime:66820800 ConnTime 66820420
*Mar  8 17:36:47: 0x624D8CCC : State change from (STATE_DISCONNECTING, SUBSTATE_NONE)  to (STATE_DEAD, SUBSTATE_NONE)
*Mar  8 17:36:47: The Call Setup Information is :
        Call Control Block (CCB) : 0x624D8CCC
         State of The Call        : STATE_DEAD
         TCP Sockets Used         : NO
         Calling Number           : 3660110
         Called Number            : 3660210
         Negotiated Codec         : g711ulaw
         Source IP Address (Media): 166.34.245.231
         Source IP Port    (Media): 20038
         Destn  IP Address (Media): 166.34.245.230
         Destn  IP Port    (Media): 20208
         Destn SIP Addr (Control) : 166.34.245.230
         Destn SIP Port (Control) : 5060
         Destination Name         : 166.34.245.230
*Mar  8 17:36:47: 
        Disconnect Cause (CC)    : 16
        Disconnect Cause (SIP)   : 200
*Mar  8 17:36:47: udpsock_close_connect: Socket fd: 1 closed for connid 1 with remote port: 5060

Examples

The following example displays debug output from one side of the call:

Router1# debug ccsip calls
SIP Call statistics tracing is enabled
Router1#
*Mar  6 14:12:33: The Call Setup Information is :
        Call Control Block (CCB) : 0x624D078C
         State of The Call        : STATE_ACTIVE
         TCP Sockets Used         : NO
         Calling Number           : 3660110
         Called Number            : 3660210
         Negotiated Codec         : g711ulaw
         Source IP Address (Media): 166.34.245.230
         Source IP Port    (Media): 20644
         Destn  IP Address (Media): 166.34.245.231
         Destn  IP Port    (Media): 20500
         Destn SIP Addr (Control) : 166.34.245.231
         Destn SIP Port (Control) : 5060
         Destination Name         : 166.34.245.231
*Mar  6 14:12:40: The Call Setup Information is :
        Call Control Block (CCB) : 0x624D078C
         State of The Call        : STATE_DEAD
         TCP Sockets Used         : NO
         Calling Number           : 3660110
         Called Number            : 3660210
         Negotiated Codec         : g711ulaw
         Source IP Address (Media): 166.34.245.230
         Source IP Port    (Media): 20644
         Destn  IP Address (Media): 166.34.245.231
         Destn  IP Port    (Media): 20500
         Destn SIP Addr (Control) : 166.34.245.231
         Destn SIP Port (Control) : 5060
         Destination Name         : 166.34.245.231
*Mar  6 14:12:40: 
        Disconnect Cause (CC)    : 16
        Disconnect Cause (SIP)   : 200

The following example displays debug output from the other side of the call:

Router2# debug ccsip calls
SIP Call statistics tracing is enabled
Router2#
*Mar  8 17:38:31: The Call Setup Information is :
        Call Control Block (CCB) : 0x624D9560
         State of The Call        : STATE_ACTIVE
         TCP Sockets Used         : NO
         Calling Number           : 3660110
         Called Number            : 3660210
         Negotiated Codec         : g711ulaw
         Source IP Address (Media): 166.34.245.231
         Source IP Port    (Media): 20500
         Destn  IP Address (Media): 166.34.245.230
         Destn  IP Port    (Media): 20644
         Destn SIP Addr (Control) : 166.34.245.230
         Destn SIP Port (Control) : 5060
         Destination Name         : 166.34.245.230
*Mar  8 17:38:38: The Call Setup Information is:
        Call Control Block (CCB) : 0x624D9560
         State of The Call        : STATE_DEAD
         TCP Sockets Used         : NO
         Calling Number           : 3660110
         Called Number            : 3660210
         Negotiated Codec         : g711ulaw
         Source IP Address (Media): 166.34.245.231
         Source IP Port    (Media): 20500
         Destn  IP Address (Media): 166.34.245.230
         Destn  IP Port    (Media): 20644
         Destn SIP Addr (Control) : 166.34.245.230
         Destn SIP Port (Control) : 5060
         Destination Name         : 166.34.245.230
*Mar  8 17:38:38: 
        Disconnect Cause (CC)    : 16
        Disconnect Cause (SIP)   : 200

Examples

The following example displays debug output from the debug ccsip dhcp command:

Router# debug ccsip dhcp
Nov 18 17:20:48.881: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_register_configured_dest_patterns: No destination patterns to Register
Nov 18 17:20:48.881: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_spi_register_free_rcb: Freeing rcb
Nov 18 17:20:48.881: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_register_reset_dns_cache: CCSIP_REGISTER:: Primary registrar DNS resolved addr reset
Nov 18 17:21:00.965: //-1/xxxxxxxxxxxx/SIP/SIP-DHCP/config_credential_trigger_reg: Query DHCP for provisioned info upon credential dhcp config
Nov 18 17:21:00.965: //-1/xxxxxxxxxxxx/SIP/SIP-DHCP/sipua_query_dhcp_reg_info: DHCP provisioned option 125 available
Nov 18 17:21:00.965: //-1/xxxxxxxxxxxx/SIP/SIP-DHCP/ccsip_gw_parse_dhcp_opt125: parsing data in option 125 of length 73
Nov 18 17:21:00.965: //-1/xxxxxxxxxxxx/SIP/SIP-DHCP/ccsip_gw_parse_dhcp_opt125: enterprise ID 210
Nov 18 17:21:00.965: //-1/xxxxxxxxxxxx/SIP/SIP-DHCP/ccsip_gw_parse_dhcp_opt125: total option data length 80
Nov 18 17:21:00.965: //-1/xxxxxxxxxxxx/SIP/SIP-DHCP/ccsip_gw_parse_dhcp_opt125: sub-option type 201 of length 6
Nov 18 17:21:00.965: //-1/xxxxxxxxxxxx/SIP/SIP-DHCP/ccsip_gw_parse_dhcp_subopt_macaddr: MAC addr 1234567890AB
Nov 18 17:21:00.969: 
Nov 18 17:21:00.969: //-1/xxxxxxxxxxxx/SIP/SIP-DHCP/ccsip_gw_parse_dhcp_opt125: sub-option type 202 of length 6
Nov 18 17:21:00.969: //-1/xxxxxxxxxxxx/SIP/SIP-DHCP/ccsip_gw_parse_dhcp_subopt_contract_num: pilot # 777777
Nov 18 17:21:00.969: //-1/xxxxxxxxxxxx/SIP/SIP-DHCP/ccsip_gw_parse_dhcp_opt125: sub-option type 203 of length 6
Nov 18 17:21:00.969: //-1/xxxxxxxxxxxx/SIP/SIP-DHCP/ccsip_gw_parse_dhcp_subopt_addn_num: secondary # 222222 (index 0)
Nov 18 17:21:00.969: //-1/xxxxxxxxxxxx/SIP/SIP-DHCP/ccsip_gw_parse_dhcp_opt125: sub-option type 203 of length 6
Nov 18 17:21:00.969: //-1/xxxxxxxxxxxx/SIP/SIP-DHCP/ccsip_gw_parse_dhcp_subopt_addn_num: secondary # 333333 (index 1)
Nov 18 17:21:00.969: //-1/xxxxxxxxxxxx/SIP/SIP-DHCP/ccsip_gw_parse_dhcp_opt125: sub-option type 203 of length 6
Nov 18 17:21:00.969: //-1/xxxxxxxxxxxx/SIP/SIP-DHCP/ccsip_gw_parse_dhcp_subopt_addn_num: secondary # 444444 (index 2)
Nov 18 17:21:00.969: //-1/xxxxxxxxxxxx/SIP/SIP-DHCP/ccsip_gw_parse_dhcp_opt125: sub-option type 203 of length 6
Nov 18 17:21:00.969: //-1/xxxxxxxxxxxx/SIP/SIP-DHCP/ccsip_gw_parse_dhcp_subopt_addn_num: secondary # 555555 (index 3)
Nov 18 17:21:00.969: //-1/xxxxxxxxxxxx/SIP/SIP-DHCP/ccsip_gw_parse_dhcp_opt125: sub-option type 203 of length 6
Nov 18 17:21:00.969: //-1/xxxxxxxxxxxx/SIP/SIP-DHCP/ccsip_gw_parse_dhcp_subopt_addn_num: secondary # 666666 (index 4)
Nov 18 17:21:00.969: //-1/xxxxxxxxxxxx/SIP/SIP-DHCP/ccsip_gw_parse_dhcp_opt125: sub-option type 204 of length 14
Nov 18 17:21:00.969: //-1/xxxxxxxxxxxx/SIP/SIP-DHCP/ccsip_gw_parse_dhcp_subopt_domain: domain sublen 5
Nov 18 17:21:00.969: //-1/xxxxxxxxxxxx/SIP/SIP-DHCP/ccsip_gw_parse_dhcp_subopt_domain: domain sublen 3
Nov 18 17:21:00.969: //-1/xxxxxxxxxxxx/SIP/SIP-DHCP/ccsip_gw_parse_dhcp_subopt_domain: domain dns:cisco.com
Nov 18 17:21:00.969: //-1/xxxxxxxxxxxx/SIP/SIP-DHCP/ccsip_gw_parse_dhcp_opt125: parsing of DHCP option 125 succeeded
Nov 18 17:21:00.969: //-1/xxxxxxxxxxxx/SIP/SIP-DHCP/sipua_query_dhcp_reg_info: DHCP provisioned SIP server addr: 9.13.2.36
Nov 18 17:21:00.969: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_register_cred_user: Sending msg type 2 to register process from parser for user 777777
Nov 18 17:21:00.969: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_spi_register_process_e164_registration: CCSIP_REGISTER:: e164 number (777777)
Nov 18 17:21:00.969: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_register_search_e164_table: ****No entry found in E164 Table
Nov 18 17:21:00.969: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIAddContextToTable: Added context(0x476FD758) with key=[1061] to table
Nov 18 17:21:00.969: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetOutboundHostAndDestHostPrivate: CCSIP: target_host : cisco.com target_port : 5060
Nov 18 17:21:00.969: //-1/000000000000/SIP/Info/sipSPIValidateAndCopyOutboundHost: CCSIP: copy target_host to outbound_host
Nov 18 17:21:00.969: //-1/000000000000/SIP/State/sipSPIChangeState: 0x476FD758 : State change from (STATE_NONE, SUBSTATE_NONE)  to (STATE_IDLE, SUBSTATE_NONE)
Nov 18 17:21:00.969: //-1/000000000000/SIP/Info/ccsip_spi_registrar_add_expires_header: Inside ccsip_spi_registrar_add_expires_header for Expires
Nov 18 17:21:00.969: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_OUTBOUND_REGISTER
Nov 18 17:21:00.969: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_register_add_to_e164_table: ****Added to E164 Table
Nov 18 17:21:00.969: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 40
Nov 18 17:21:00.969: //-1/000000000000/SIP/Info/act_idle_outgoing_register: In act_idle_outgoing_register
Nov 18 17:21:00.969: //1034/000000000000/SIP/Info/act_idle_outgoing_register:  Send REGISTER to cisco.com:5060
Nov 18 17:21:00.969: //1034/000000000000/SIP/Info/sipSPIUaddCcbToUACTable: ****Adding to UAC table.
Nov 18 17:21:00.969: //1034/000000000000/SIP/Info/sipSPIUaddCcbToTable: Added to table. ccb=0x476FD758 key=1AF6E28A-B4CC11DD-81078B9C-6E99E02B
Nov 18 17:21:00.969: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_DNS_RESOLVE
Nov 18 17:21:00.969: //1034/000000000000/SIP/State/sipSPIChangeState: 0x476FD758 : State change from (STATE_IDLE, SUBSTATE_NONE)  to (STATE_IDLE, SUBSTATE_SENT_DNS)
Nov 18 17:21:00.969: //1034/000000000000/SIP/State/sipSPIChangeState: 0x476FD758 : State change from (STATE_IDLE, SUBSTATE_SENT_DNS)  to (SIP_STATE_OUTGOING_REGISTER, SUBSTATE_SENT_DNS)
Nov 18 17:21:00.969: //-1/xxxxxxxxxxxx/SIP/Info/sip_dns_type_srv_query: TYPE SRV query for _sip._udp.cisco.com and type:1
Nov 18 17:21:00.977: //-1/xxxxxxxxxxxx/SIP/Info/sip_dns_type_a_aaaa_query: DNS query for cisco.com and type:1
Nov 18 17:21:00.977: //-1/xxxxxxxxxxxx/SIP/Info/sip_dns_type_a_query: TYPE A query successful for cisco.com
Nov 18 17:21:00.977: //-1/xxxxxxxxxxxx/SIP/Info/sip_dns_type_a_aaaa_query: IP Address of cisco.com is:
Nov 18 17:21:00.977: //-1/xxxxxxxxxxxx/SIP/Info/sip_dns_type_a_aaaa_query: 9.13.2.36
Nov 18 17:21:00.977: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 43
Nov 18 17:21:00.977: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_register_set_dns_resolved_address: CCSIP_REGISTER:: Primary registrar DNS resolved addr set to 0.0.0.1:151847460
Nov 18 17:21:00.977: //-1/xxxxxxxxxxxx/SIP/Info/ccsipRegisterStartExpiresTimer: Starting timer for pattern  for 3600 seconds
Nov 18 17:21:00.977: //1034/000000000000/SIP/State/sipSPIChangeState: 0x476FD758 : State change from (SIP_STATE_OUTGOING_REGISTER, SUBSTATE_SENT_DNS)  to (SIP_STATE_OUTGOING_REGISTER, SUBSTATE_NONE)
Nov 18 17:21:00.977: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Clock Time Zone is UTC, same as GMT: Using GMT
Nov 18 17:21:00.981: //1034/000000000000/SIP/Info/sipSPISendRegister: Associated container=0x46794ACC to Register
Nov 18 17:21:00.981: //1034/000000000000/SIP/Transport/sipSPISendRegister: Sending REGISTER to the transport layer
Nov 18 17:21:00.981: //1034/000000000000/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Dial peer configuration, Switch Transport is FALSE
Nov 18 17:21:00.981: //1034/000000000000/SIP/Transport/sipSPITransportSendMessage: msg=0x4707F998, addr=9.13.2.36, port=5060, sentBy_port=0, is_req=1, transport=1, switch=0, callBack=0x415A53B0
Nov 18 17:21:00.981: //1034/000000000000/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately
Nov 18 17:21:00.981: //1034/000000000000/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0
Nov 18 17:21:00.981: //1034/000000000000/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x4707F998
Nov 18 17:21:00.981: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x4707F998, addr=9.13.2.36, port=5060, connId=2 for UDP
Nov 18 17:21:00.981: //1034/000000000000/SIP/State/sipSPIChangeState: 0x476FD758 : State change from (SIP_STATE_OUTGOING_REGISTER, SUBSTATE_NONE)  to (SIP_STATE_OUTGOING_REGISTER, SUBSTATE_NONE)
Nov 18 17:21:00.981: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent: 
REGISTER sip:cisco.com:5060 SIP/2.0
Date: Tue, 18 Nov 2008 17:21:00 GMT
From: <sip:777777@cisco.com>;tag=34FBAED8-131
Supported: path
Timestamp: 1227028860
Content-Length: 0
User-Agent: Cisco-SIPGateway/IOS-12.x
To: <sip:777777@cisco.com>
Contact: <sip:777777@9.13.8.183:5060>
Expires:  3600
Call-ID: 1AF6E28A-B4CC11DD-81078B9C-6E99E02B          
Via: SIP/2.0/UDP 9.13.8.183:5060;branch=z9hG4bK3F522D9
CSeq: 2 REGISTER
Max-Forwards: 70
Nov 18 17:21:00.981: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [9.13.2.36]:56305
Nov 18 17:21:00.981: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1
Nov 18 17:21:00.981: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x00000000
Nov 18 17:21:00.985: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog
Nov 18 17:21:00.985: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received: 
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 9.13.8.183:5060;received=9.13.8.183;branch=z9hG4bK3F522D9
Call-ID: 1AF6E28A-B4CC11DD-81078B9C-6E99E02B
From: <sip:777777@cisco.com>;tag=34FBAED8-131
To: <sip:777777@cisco.com>
CSeq: 2 REGISTER
Content-Length: 0
Nov 18 17:21:01.077: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [9.13.2.36]:56306
Nov 18 17:21:01.077: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1
Nov 18 17:21:01.077: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x00000000
Nov 18 17:21:01.077: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog
Nov 18 17:21:01.077: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received: 
SIP/2.0 200 OK
Via: SIP/2.0/UDP 9.13.8.183:5060;received=9.13.8.183;branch=z9hG4bK3F522D9          
Call-ID: 1AF6E28A-B4CC11DD-81078B9C-6E99E02B
From: <sip:777777@cisco.com>;tag=34FBAED8-131
To: <sip:777777@cisco.com>
CSeq: 2 REGISTER
Contact: <sip:777777@9.13.8.183:5060>;expires=3600
Content-Length: 0
Nov 18 17:21:01.077: //1034/000000000000/SIP/Info/ccsip_gw_register_process_response: No P-Assoicated-URI present in Register Response
Nov 18 17:21:01.077: //-1/xxxxxxxxxxxx/SIP/Info/ccsipRegisterStartExpiresTimer: Starting timer for pattern 777777 for 2880 seconds
Nov 18 17:21:01.077: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIDeleteContextFromTable: Context for key=[1061] removed.
Nov 18 17:21:01.077: //1034/000000000000/SIP/Info/sipSPIUdeleteCcbFromUACTable: ****Deleting from UAC table.
Nov 18 17:21:01.077: //1034/000000000000/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x476FD758 key=1AF6E28A-B4CC11DD-81078B9C-6E99E02B
Nov 18 17:21:01.077: //1034/000000000000/SIP/Info/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd
Nov 18 17:21:01.077: //1034/000000000000/SIP/Info/ccsip_qos_cleanup: Entry
Nov 18 17:21:01.077: //1034/000000000000/SIP/Info/sipSPI_ipip_free_codec_profile: Codec Profiles Freed
Nov 18 17:21:01.077: //1034/000000000000/SIP/Info/sipSPIUfreeOneCCB: Freeing ccb 476FD758
Nov 18 17:21:01.081: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContextFromTable: NO context for key[1061]
Nov 18 17:21:02.761: %SYS-5-CONFIG_I: Configured from console by console
CUBE-DHCP-CLIENT1#