Voice over IP for the Cisco 3600 Series Debug Commands

Table of Contents

Voice Over IP Debug Commands

Voice Over IP Debug Commands

This section documents new debug commands. All other commands used with this feature are documented in the Cisco IOS Release 11.3 Debug Command Reference.

  • debug voip ccapi error

  • debug voip ccapi inout

  • debug vpm all

  • debug vpm dsp

  • debug vpm port

  • debug vpm signal

  • debug vpm spi

debug voip ccapi error

Use the debug voip ccapi error EXEC command to trace error logs in the call control API. Use the no form of this command to disable debugging output.

[no] debug voip ccapi error

Usage Guidelines

The debug voip ccapi error EXEC command traces the error logs in the call control API. Error logs are generated during normal call processing, when there are insufficient resources, or when there are problems in the underlying network-specific code, the higher call session application, or the call control API itself.

This debug command shows error events or unexpected behavior in system software. In most cases, no events will be generated.

debug voip ccapi inout

Use the debug voip ccapi inout EXEC command to trace the execution path through the call control API. Use the no form of this command to disable debugging output.

[no] debug voip ccapi inout

Usage Guidelines

The debug voip ccapi inout EXEC command traces the execution path through the call control API, which serves as the interface between the call session application and the underlying network-specific software. You can use the output from this command to understand how calls are being handled by the router.

This command shows how a call flows through the system. Using this debug level, you can see the call setup and teardown operations performed on both the telephony and network call legs.

Sample Display

The following output shows the call setup indicated and accepted by the router:

router# debug voip ccapi inout

cc_api_call_setup_ind (vdbPtr=0x60BFB530, callInfo={called=, calling=, fdest=0}, 
callID=0x60BFAEB8)
cc_process_call_setup_ind (event=0x60B68478)
sess_appl: ev(14), cid(1), disp(0)
ccCallSetContext (callID=0x1, context=0x60A7B094)
ccCallSetPeer (callID=0x1, peer=0x60C0A868, voice_peer_tag=2, encapType=1, 
dest-pat=+14085231001, answer=)
ccCallSetupAck (callID=0x1)
 

The following output shows the caller entering DTMF digits until a dial-peer is matched:

cc_api_call_digit (vdbPtr=0x60BFB530, callID=0x1, digit=4, mode=0)
sess_appl: ev(8), cid(1), disp(0)
ssa: cid(1)st(0)oldst(0)cfid(-1)csize(0)in(1)fDest(0)
cc_api_call_digit (vdbPtr=0x60BFB530, callID=0x1, digit=1, mode=0)
sess_appl: ev(8), cid(1), disp(0)
ssa: cid(1)st(0)oldst(0)cfid(-1)csize(0)in(1)fDest(0)
cc_api_call_digit (vdbPtr=0x60BFB530, callID=0x1, digit=0, mode=0)
sess_appl: ev(8), cid(1), disp(0)
ssa: cid(1)st(0)oldst(0)cfid(-1)csize(0)in(1)fDest(0)
cc_api_call_digit (vdbPtr=0x60BFB530, callID=0x1, digit=0, mode=0)
sess_appl: ev(8), cid(1), disp(0)
ssa: cid(1)st(0)oldst(0)cfid(-1)csize(0)in(1)fDest(0)
cc_api_call_digit (vdbPtr=0x60BFB530, callID=0x1, digit=1, mode=0)
sess_appl: ev(8), cid(1), disp(0)
ssa: cid(1)st(0)oldst(0)cfid(-1)csize(0)in(1)fDest(0)
ccCallProceeding (callID=0x1, prog_ind=0x0)
ssaSetupPeer cid(1), destPat(+14085241001), matched(8), prefix(), peer(60C0E710)
 

The following output shows the call setup over the IP network to the remote router:

ccCallSetupRequest (peer=0x60C0E710, dest=, params=0x60A7B0A8 mode=0, 
*callID=0x60B6C110)
ccIFCallSetupRequest: (vdbPtr=0x60B6C5D4, dest=, callParams={called=+14085241001, 
calling=+14085231001, fdest=0, voice_peer_tag=104}, mode=0x0)
ccCallSetContext (callID=0x2, context=0x60A7B2A8)
 

The following output shows the called party is alerted, a codec is negotiated, and voice path is cut through:

cc_api_call_alert(vdbPtr=0x60B6C5D4, callID=0x2, prog_ind=0x8, sig_ind=0x1)
sess_appl: ev(6), cid(2), disp(0)
ssa: cid(2)st(1)oldst(0)cfid(-1)csize(0)in(0)fDest(0)-cid2(1)st2(1)oldst2(0)
ccCallAlert (callID=0x1, prog_ind=0x8, sig_ind=0x1)
ccConferenceCreate (confID=0x60B6C150, callID1=0x1, callID2=0x2, tag=0x0)
cc_api_bridge_done (confID=0x1, srcIF=0x60B6C5D4, srcCallID=0x2, dstCallID=0x1, 
disposition=0, tag=0x0)
cc_api_bridge_done (confID=0x1, srcIF=0x60BFB530, srcCallID=0x1, dstCallID=0x2, 
disposition=0, tag=0x0)
cc_api_caps_ind (dstVdbPtr=0x60B6C5D4, dstCallId=0x2,srcCallId=0x1, caps={codec=0x7, 
fax_rate=0x7F, vad=0x3})
cc_api_caps_ind (dstVdbPtr=0x60BFB530, dstCallId=0x1,srcCallId=0x2, caps={codec=0x4, 
fax_rate=0x2, vad=0x2})
cc_api_caps_ack (dstVdbPtr=0x60BFB530, dstCallId=0x1,srcCallId=0x2, caps={codec=0x4, 
fax_rate=0x2, vad=0x2})
cc_api_caps_ack (dstVdbPtr=0x60B6C5D4, dstCallId=0x2,srcCallId=0x1, caps={codec=0x4, 
fax_rate=0x2, vad=0x2})
sess_appl: ev(17), cid(1), disp(0)
ssa: cid(1)st(3)oldst(0)cfid(1)csize(0)in(1)fDest(0)-cid2(2)st2(3)oldst2(1)
 

The following output shows that the call is connected and voice is active:

cc_api_call_connected(vdbPtr=0x60B6C5D4, callID=0x2)
sess_appl: ev(7), cid(2), disp(0)
ssa: cid(2)st(4)oldst(1)cfid(1)csize(0)in(0)fDest(0)-cid2(1)st2(4)oldst2(3)
ccCallConnect (callID=0x1)
 

The following output shows how the system processes voice statistics and monitors voice quality during the call:

ccapi_request_rt_packet_stats (requestorIF=0x60B6C5D4, requestorCID=0x2,
      requestedCID=0x1, tag=0x60A7C598)
cc_api_request_rt_packet_stats_done (requestedIF=0x60BFB530, requestedCID=0x1,
      tag=0x60A7A4C4)
ccapi_request_rt_packet_stats (requestorIF=0x60B6C5D4, requestorCID=0x2,
      requestedCID=0x1, tag=0x60A7C598)
cc_api_request_rt_packet_stats_done (requestedIF=0x60BFB530, requestedCID=0x1,
      tag=0x60C1FE54)
ccapi_request_rt_packet_stats (requestorIF=0x60B6C5D4, requestorCID=0x2,
      requestedCID=0x1, tag=0x60A7C598)
cc_api_request_rt_packet_stats_done (requestedIF=0x60BFB530, requestedCID=0x1,
      tag=0x60A7A5F4)
ccapi_request_rt_packet_stats (requestorIF=0x60B6C5D4, requestorCID=0x2,
      requestedCID=0x1, tag=0x60A7C598)
cc_api_request_rt_packet_stats_done (requestedIF=0x60BFB530, requestedCID=0x1,
      tag=0x60A7A6D8)
ccapi_request_rt_packet_stats (requestorIF=0x60B6C5D4, requestorCID=0x2,
      requestedCID=0x1, tag=0x60A7C598)
cc_api_request_rt_packet_stats_done (requestedIF=0x60BFB530, requestedCID=0x1,
      tag=0x60A7ACBC)
 

The following output shows that disconnection is indicated from the calling party, call legs are torn down and disconnected:

cc_api_call_disconnected(vdbPtr=0x60BFB530, callID=0x1, cause=0x10)
sess_appl: ev(9), cid(1), disp(0)
ssa: cid(1)st(5)oldst(3)cfid(1)csize(0)in(1)fDest(0)-cid2(2)st2(5)oldst2(4)
ccConferenceDestroy (confID=0x1, tag=0x0)
cc_api_bridge_done (confID=0x1, srcIF=0x60B6C5D4, srcCallID=0x2, dstCallID=0x1, 
disposition=0 tag=0x0)
cc_api_bridge_done (confID=0x1, srcIF=0x60BFB530, srcCallID=0x1, dstCallID=0x2, 
disposition=0 tag=0x0)
sess_appl: ev(18), cid(1), disp(0)
ssa: cid(1)st(6)oldst(5)cfid(-1)csize(0)in(1)fDest(0)-cid2(2)st2(6)oldst2(4)
ccCallDisconnect (callID=0x1, cause=0x10 tag=0x0)
ccCallDisconnect (callID=0x2, cause=0x10 tag=0x0)
cc_api_call_disconnect_done(vdbPtr=0x60B6C5D4, callID=0x2, disp=0, tag=0x0)
sess_appl: ev(10), cid(2), disp(0)
ssa: cid(2)st(7)oldst(4)cfid(-1)csize(0)in(0)fDest(0)-cid2(1)st2(7)oldst2(6)
cc_api_call_disconnect_done(vdbPtr=0x60BFB530, callID=0x1, disp=0, tag=0x0)
sess_appl: ev(10), cid(1), disp(0)
ssa: cid(1)st(7)oldst(6)cfid(-1)csize(1)in(1)fDest(0)

debug vpm all

Use the debug vpm all EXEC command to enable debugging on all VPM areas. Use the no form of this command to disable debugging output.

[no] debug vpm all

Usage Guidelines

The debug vpm all EXEC command enables all of the debug vpm commands: debug vpm spi, debug vpm signal, and debug vpm dsp. For more information or sample output, refer to the individual commands in this chapter.

debug vpm dsp

Use the debug vpm dsp EXEC command to show messages from the DSP on the VPM to the router. Use the no form of this command to disable debugging output.

[no] debug vpm dsp

Usage Guidelines

The debug vpm dsp command shows messages from the DSP on the VPM to the router; this command can be useful if you suspect that the VPM is not functional. It is a simple way to check if the VPM is responding to off-hook indications and to evaluate timing for signaling messages from the interface.

Sample Display

The following output shows the DSP timestamp and the router timestamp for each event and, for SIG_STATUS, the state value shows the state of the ABCD bits in the signaling message. This sample shows a call coming in on an FXO interface.

The router waits for ringing to terminate before accepting the call. State=0x0 indicates ringing; state 0x4 indicates not ringing:

ssm_dsp_message: SEND/RESP_SIG_STATUS: state=0x0 timestamp=58172 systime=40024

ssm_dsp_message: SEND/RESP_SIG_STATUS: state=0x4 timestamp=59472 systime=40154

ssm_dsp_message: SEND/RESP_SIG_STATUS: state=0x4 timestamp=59589 systime=40166

 

The following output shows the digits collected:

vcsm_dsp_message: MSG_TX_DTMF_DIGIT: digit=4
vcsm_dsp_message: MSG_TX_DTMF_DIGIT: digit=1
vcsm_dsp_message: MSG_TX_DTMF_DIGIT: digit=0
vcsm_dsp_message: MSG_TX_DTMF_DIGIT: digit=0
vcsm_dsp_message: MSG_TX_DTMF_DIGIT: digit=0
 

This shows the disconnect indication and the final call statistics reported by the DSP (which are then populated in the call history table):

ssm_dsp_message: SEND/RESP_SIG_STATUS: state=0xC timestamp=21214 systime=42882
vcsm_dsp_message: MSG_TX_GET_TX_STAT: num_tx_pkts=1019 num_signaling_pkts=0 
num_comfort_noise_pkts=0 transmit_durtation=24150 voice_transmit_duration=20380 
fax_transmit_duration=0

debug vpm port

Use the debug vpm port EXEC command to limit the debug output to a particular port. Use the no form of this command to disable debugging output.

[no] debug vpm port slot-number/subunit-number/port

Syntax Description

slot-number/

Specifies the slot number in the Cisco router where the voice interface card is installed. Valid entries are from 0 to 3, depending on the slot where it has been installed.

subunit-number/

Specifies the subunit on the voice interface card where the voice port is located. Valid entries are 0 or 1.

port

Specifies the voice port. Valid entries are 0 or 1.

Usage Guidelines

Use the debug vpm port command to limit the debug output to a particular port. The debug output can be quite voluminous for a single channel. A 12-port box might create problems. Use this debug with any or all of the other debug modes.

For example, the following shows debug vpm dsp messages only for port 1/0/0:

debug vpm dsp
debug vpm port 1/0/0
 

The following shows the debug vpm signal messages only for ports 1/0/0 and 1/0/1:

debug vpm signal
debug vpm port 1/0/0
debug vpm port 1/0/1
 

The following shows how to turn off debugging on a port:

no debug vpm port 1/0/0
 

The following produces no output because port level debugs work in conjunction with other levels:

debug vpm port 1/0/0
 

Execution of no debug all will turn off all port level debugging. It is usually a good idea to turn off all debugging and then enter the debug commands you are interested in one by one. This will help to avoid confusion about which ports you are actually debugging.

debug vpm signal

Use the debug vpm signal EXEC command to collect debug information only for signaling events. Use the no form of this command to disable debugging output.

[no] debug vpm signal

Usage Guidelines

The debug vpm signal EXEC command to collect debug information only for signaling events. This command can also be useful in resolving problems with signaling to a PBX.

Sample Display

The following output shows that a ring is detected, and that the router waits for the ringing to stop before accepting the call:

ssm_process_event: [1/0/1, 0.2, 15] fxols_onhook_ringing
ssm_process_event: [1/0/1, 0.7, 19] fxols_ringing_not
ssm_process_event: [1/0/1, 0.3, 6] 
ssm_process_event: [1/0/1, 0.3, 19] fxols_offhook_clear
 

The following output shows that the call is connected:

ssm_process_event: [1/0/1, 0.3, 4] fxols_offhook_proc
ssm_process_event: [1/0/1, 0.3, 8] fxols_proc_voice
ssm_process_event: [1/0/1, 0.3, 5] fxols_offhook_connect
 

The following output confirms a disconnect from the switch and release with higher layer code:

ssm_process_event: [1/0/1, 0.4, 27] fxols_offhook_disc
ssm_process_event: [1/0/1, 0.4, 33] fxols_disc_confirm
ssm_process_event: [1/0/1, 0.4, 3] fxols_offhook_release

debug vpm spi

Use the debug vpm spi EXEC command to trace how the voice port module SPI interfaces with the call control API. Use the no form of this command to disable debugging output.

[no] debug vpm spi

Usage Guidelines

The debug vpm spi EXEC command traces how the voice port module SPI interfaces with the call control API. This debug command displays information about how each network indication and application request is handled.

This debug level shows the internal workings of the voice telephony call state machine.

Sample Display

The following output shows that the call is accepted and presented to a higher layer code:

dsp_set_sig_state: [1/0/1] packet_len=14 channel_id=129 packet_id=39 state=0xC 
timestamp=0x0
vcsm_process_event: [1/0/1, 0.5, 1] act_up_setup_ind
 

The following output shows that the higher layer code accepts the call, requests addressing information, and starts DTMF and dial-pulse collection. This also shows that the digit timer is started.

vcsm_process_event: [1/0/1, 0.6, 11] act_setup_ind_ack
dsp_voice_mode: [1/0/1] packet_len=22 channel_id=1 packet_id=73 coding_type=1 
voice_field_size=160 VAD_flag=0 echo_length=128 comfort_noise=1 fax_detect=1
dsp_dtmf_mode: [1/0/1] packet_len=12 channel_id=1 packet_id=65 dtmf_or_mf=0
dsp_CP_tone_on: [1/0/1] packet_len=32 channel_id=1 packet_id=72 tone_id=3 n_freq=2 
freq_of_first=350 freq_of_second=440 amp_of_first=4000 amp_of_second=4000 direction=1 
on_time_first=65535 off_time_first=0 on_time_second=65535 off_time_second=0
dsp_digit_collect_on: [1/0/1] packet_len=22 channel_id=129 packet_id=35 
min_inter_delay=550 max_inter_delay=3200 mim_make_time=18 max_make_time=75 
min_brake_time=18 max_brake_time=75
vcsm_timer: 46653
 

The following output shows the collection of digits one by one until the higher level code indicates it has enough. The input timer is restarted with each digit and the device waits in idle mode for connection to proceed.

vcsm_process_event: [1/0/1, 0.7, 25] act_dcollect_digit
dsp_CP_tone_off: [1/0/1] packet_len=10 channel_id=1 packet_id=71
vcsm_timer: 47055
vcsm_process_event: [1/0/1, 0.7, 25] act_dcollect_digit
dsp_CP_tone_off: [1/0/1] packet_len=10 channel_id=1 packet_id=71
vcsm_timer: 47079
vcsm_process_event: [1/0/1, 0.7, 25] act_dcollect_digit
dsp_CP_tone_off: [1/0/1] packet_len=10 channel_id=1 packet_id=71
vcsm_timer: 47173
vcsm_process_event: [1/0/1, 0.7, 25] act_dcollect_digit
dsp_CP_tone_off: [1/0/1] packet_len=10 channel_id=1 packet_id=71
vcsm_timer: 47197
vcsm_process_event: [1/0/1, 0.7, 25] act_dcollect_digit
dsp_CP_tone_off: [1/0/1] packet_len=10 channel_id=1 packet_id=71
vcsm_timer: 47217
vcsm_process_event: [1/0/1, 0.7, 13] act_dcollect_proc
dsp_CP_tone_off: [1/0/1] packet_len=10 channel_id=1 packet_id=71
dsp_digit_collect_off: [1/0/1] packet_len=10 channel_id=129 packet_id=36
dsp_idle_mode: [1/0/1] packet_len=10 channel_id=1 packet_id=68

The following output shows that the network voice path cuts through:

vcsm_process_event: [1/0/1, 0.8, 15] act_bridge
vcsm_process_event: [1/0/1, 0.8, 20] act_caps_ind
vcsm_process_event: [1/0/1, 0.8, 21] act_caps_ack
dsp_voice_mode: [1/0/1] packet_len=22 channel_id=1 packet_id=73 coding_type=6 
voice_field_size=20 VAD_flag=1 echo_length=128 comfort_noise=1 fax_detect=1
 

The following output shows that the called-party end of the connection is connected:

vcsm_process_event: [1/0/1, 0.8, 8] act_connect
 

The following output shows the voice quality statistics collected periodically:

vcsm_process_event: [1/0/1, 0.13, 17] 
dsp_get_rx_stats: [1/0/1] packet_len=12 channel_id=1 packet_id=87 reset_flag=0
vcsm_process_event: [1/0/1, 0.13, 28] 
vcsm_process_event: [1/0/1, 0.13, 29] 
vcsm_process_event: [1/0/1, 0.13, 32] 
vcsm_process_event: [1/0/1, 0.13, 17] 
dsp_get_rx_stats: [1/0/1] packet_len=12 channel_id=1 packet_id=87 reset_flag=0
vcsm_process_event: [1/0/1, 0.13, 28] 
vcsm_process_event: [1/0/1, 0.13, 29] 
vcsm_process_event: [1/0/1, 0.13, 32] 
vcsm_process_event: [1/0/1, 0.13, 17] 
dsp_get_rx_stats: [1/0/1] packet_len=12 channel_id=1 packet_id=87 reset_flag=0
vcsm_process_event: [1/0/1, 0.13, 28] 
vcsm_process_event: [1/0/1, 0.13, 29] 
vcsm_process_event: [1/0/1, 0.13, 32] 
 

The following output shows that the disconnection indication is passed to higher level code. The call connection is torn down, and final call statistics are collected:

vcsm_process_event: [1/0/1, 0.13, 4] act_generate_disc
vcsm_process_event: [1/0/1, 0.13, 16] act_bdrop
dsp_CP_tone_off: [1/0/1] packet_len=10 channel_id=1 packet_id=71
vcsm_process_event: [1/0/1, 0.13, 18] act_disconnect
dsp_get_levels: [1/0/1] packet_len=10 channel_id=1 packet_id=89
vcsm_timer: 48762
vcsm_process_event: [1/0/1, 0.15, 34] act_get_levels
dsp_get_tx_stats: [1/0/1] packet_len=12 channel_id=1 packet_id=86 reset_flag=1
vcsm_process_event: [1/0/1, 0.15, 31] act_stats_complete
dsp_CP_tone_off: [1/0/1] packet_len=10 channel_id=1 packet_id=71
dsp_digit_collect_off: [1/0/1] packet_len=10 channel_id=129 packet_id=36
dsp_idle_mode: [1/0/1] packet_len=10 channel_id=1 packet_id=68
vcsm_timer: 48762
dsp_set_sig_state: [1/0/1] packet_len=14 channel_id=129 packet_id=39 state=0x4 
timestamp=0x0
vcsm_process_event: [1/0/1, 0.16, 5] act_wrelease_release
dsp_CP_tone_off: [1/0/1] packet_len=10 channel_id=1 packet_id=71
dsp_idle_mode: [1/0/1] packet_len=10 channel_id=1 packet_id=68
dsp_get_rx_stats: [1/0/1] packet_len=12 channel_id=1 packet_id=87 reset_flag=1