|
|
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.
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 errorThe 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.
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 inoutThe 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.
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)
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 allThe 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.
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 dspThe 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.
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=40024ssm_dsp_message: SEND/RESP_SIG_STATUS: state=0x4 timestamp=59472 systime=40154ssm_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
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| 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. |
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.
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 signalThe 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.
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
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 spiThe 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.
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
|
|