|
|
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.
slot/dspm/dsp/dsp-channel | Identifies the location of a particular DSP channel. |
The debug csm voice EXEC command turns on debugging for all CMS Voice over IP calls. If this command has no keyword specified, then debugging is enabled for all voice calls. The no debug cams voice command turns off debugging information for all voice calls.
If the keyword slot/dspm/dsp/dsp-channel is specified, then (if the specified dsp channel is engaged in a CSM call) CMS call-related debugging information will be turned on for this channel. The no form of this command turns off debugging for that particular channel.
The following examples show sample output from the debug csm voice command. Figure 13 shows that CSM has received an event from ISDN.
Oct 18 04:05:07.052: EVENT_FROM_ISDN::dchan_idb=0x60D7B6B8, call_id=0xCF, ces=0x1 bchan=0x0, event=0x1, cause=0x0
In this example:
Figure 14 shows that CSM has allocated the CSM voice control block for the DSP device on slot 1 port 10 for this call.
Oct 18 04:05:07.052: VDEV_ALLOCATE: slot 1 and port 10 is allocated.
This AS5300 might not be actually used to handle this call. CSM must first allocate the CSM voice control block to initiate the state machine. After the voice control block has been allocated, CSM obtains from DSP Resource Manager the actual DSP channel that will be used for the call. At that point, CSM will switch over to the actual logical port number. The slot number refers to the physical slot on the AS5300. The port number is the logical DSP number interpreted as listed in Table 15.
| Logical Port Number | Physical DSP Channel |
|---|---|
Port 0 | DSPRM 1, DSP 1, DSP channel 1 |
Port 1 | DSPRM 1, DSP 1, DSP channel 2 |
Port 2 | DSPRM 1, DSP 2, DSP channel 1 |
Port 3 | DSPRM 1, DSP 2, DSP channel 2 |
Port 4 | DSPRM 1, DSP 3, DSP channel 1 |
Port 5 | DSPRM 1, DSP 3, DSP channel 2 |
Port 6 | DSPRM 1, DSP 4, DSP channel 1 |
Port 7 | DSPRM 1, DSP 4, DSP channel 2 |
Port 8 | DSPRM 1, DSP 5, DSP channel 1 |
Port 9 | DSPRM 1, DSP 5, DSP channel 2 |
Port 10 | DSPRM 1, DSP 6, DSP channel 1 |
Port 11 | DSPRM 1, DSP 6, DSP channel 2 |
Port 12 | DSPRM 2, DSP 1, DSP channel 1 |
Port 13 | DSPRM 2, DSP 1, DSP channel 2 |
Port 14 | DSPRM 2, DSP 2, DSP channel 1 |
Port 15 | DSPRM 2, DSP 2, DSP channel 2 |
Port 16 | DSPRM 2, DSP 3, DSP channel 1 |
Port 17 | DSPRM 2, DSP 3, DSP channel 2 |
Port 18 | DSPRM 2, DSP 4, DSP channel 1 |
Port 19 | DSPRM 2, DSP 4, DSP channel 2 |
Port 20 | DSPRM 2, DSP 5, DSP channel 1 |
Port 21 | DSPRM 2, DSP 5, DSP channel 2 |
Port 22 | DSPRM 2, DSP 6, DSP channel 1 |
Port 23 | DSPRM 2, DSP 6, DSP channel 2 |
Port 48 | DSPRM 5, DSP 1, DSP channel 1 |
Port 49 | DSPRM 5, DSP 1, DSP channel 2 |
Port 50 | DSPRM 5, DSP 2, DSP channel 1 |
Port 51 | DSPRM 5, DSP 2, DSP channel 2 |
Port 52 | DSPRM 5, DSP 3, DSP channel 1 |
Port 53 | DSPRM 5, DSP 3, DSP channel 2 |
Port 54 | DSPRM 5, DSP 4, DSP channel 1 |
Port 55 | DSPRM 5, DSP 4, DSP channel 2 |
Port 56 | DSPRM 5, DSP 5, DSP channel 1 |
Port 57 | DSPRM 5, DSP 5, DSP channel 2 |
Port 58 | DSPRM 5, DSP 6, DSP channel 1 |
Port 59 | DSPRM 5, DSP 6, DSP channel 2 |
Figure 15 shows that the function csm_vtsp_init_tdm() has been called with a voice control block of address 0x60B8562C. This function will only be called when the call is treated as a voice call.
Oct 18 04:05:07.052: csm_vtsp_init_tdm (voice_vdev=0x60B8562C)
Figure 16 shows that CSM has obtained a DSP channel from the DSP Resource Manager.
Oct 18 04:05:07.052: csm_vtsp_init_tdm: dsprm_tdm_allocate: tdm slot 1, dspm 2, dsp 5, dsp_channel 1csm_vtsp_init_tdm: dsprm_tdm_allocate: tdm stream 5, channel 9, bank 0, bp_channel 10
The DSP channel has the following initialized TDM channel information:
Figure 17 shows that CSM has received an incoming call event from ISDN.
Oct 18 04:05:07.052: EVENT_FROM_ISDN:(00CF): DEV_INCALL at slot 1 and port 20
Slot 1, port 20 means the logical DSP channel 20 (mapped to DSPRM 2, DSP 5, DSP channel 1).
Figure 18 shows that the DEV_INCALL message has been translated into CSM_EVENT_ISDN_CALL message
Oct 18 04:05:07.052: CSM_PROC_IDLE: CSM_EVENT_ISDN_CALL at slot 1, port 20
This message is passed to the CSM central state machine while it is in the CSM_IDLE state and is in the CSM_PROC_IDLE procedure. The logical DSP channel port 20 on slot 1 is used to handle this call.
Figure 19 shows that CSM has invoked the vtsp_ic_notify() function with a CSM voice call control block 0x60B8562C.
Oct 18 04:05:07.052: vtsp_ic_notify : (voice_vdev= 0x60B8562C)
Inside this function, CSM will send a SETUP INDICATION message to VTSP. This function will only be invoked if the call is a voice call.
Figure 20 shows that CSM has received a SETUP INDICATION RESPONSE message from VTSP as an acknowledgement.
Oct 18 04:05:07.056: csm_vtsp_call_setup_resp (vdev_info=0x60B8562C, vtsp_cdb=0x60FCA114)
This means that VTSP has received the CALL SETUP INDICATION message previously sent and has proceeded to process the call.
Figure 21 shows that CSM has received a CALL CONNECT message from VTSP.
Oct 18 04:05:07.596: csm_vtsp_call_connect (vtsp_cdb=0x60FCA114, voice_vdev=0x60B8562C)
This indicates that VTSP has received a CONNECT for the call leg initiated to the Internet side.
Figure 22 shows that while CSM is in the CSM_IC2_RING state, it receives a SETUP INDICATION RESPONSE from VTSP. This message is translated into CSM_EVENT_MODEM_OFFHOOK and passed to the CSM central state machine.
Oct 18 04:05:07.596: CSM_PROC_IC2_RING: CSM_EVENT_MODEM_OFFHOOK at slot 1, port 20
Figure 23 shows that CSM has received a CONNECT message from ISDN for the call using the logical DSP channel on slot 1 and port 20.
Oct 18 04:05:07.616: EVENT_FROM_ISDN:(00CF): DEV_CONNECTED at slot 1 and port 20
Figure 24 shows that CSM has translated the CONN ECT event from ISDN into the CSM_EVENT_ISDN_CONNECTED message, which is then passed to the CSM central state machine.
Oct 18 04:05:07.616: CSM_PROC_IC4_WAIT_FOR_CARRIER: CSM_EVENT_ISDN_CONNECTED at slot 1, port 20
Figure 25 shows that CSM has received a CALL SETUP REQUEST from VTSP.
May 16 12:22:27.580: csm_vtsp_call_setup_request (vtsp_cdb=0x60FCFA20, vtsp_sdb=0x60DFB608)
This represents a request to make an outgoing call to the PSTN.
Figure 26 shows that the physical DSP channel has been allocated for this outgoing call.
May 16 12:22:27.580: csm_vtsp_call_setup_request: tdm slot 1, dspm 5, dsp 4, dsp_channel 1
Figure 27 shows the on-chip and backplane tdm channel assigned to this DSP channel.
May 16 12:22:27.580: csm_vtsp_call_setup_request: tdm stream 5, channel 25, bank 0, bp_channel 27
In this sample output, tdm stream 5, channel 25, bank 0, bp_channel 27 indicates the on-chip and backplane tdm channel assigned to this dsp channel. Stream 5, channel 25 gives the on-chip tdm channel mapped to the DSP; bank 0, bp_channel 27 means backplane stream 0, backplane channel #1 is assigned to this DSP.
Figure 28 shows the calling number and the called number for this call.
May 16 12:22:27.580: csm_vtsp_call_setup_request: calling number: 10001, called number: 30001
Figure 29 shows that the CALL SETUP REQUEST from VTSP has been translated into the ' CSM_EVENT_MODEM_OFFHOOK message and is passed to the CSM central state machine.
May 16 12:22:27.580: CSM_PROC_IDLE: CSM_EVENT_MODEM_OFFHOOK at slot 1, port 54
The logical DSP channel number for the DSP (slot 1, port 54) is now displayed, which maps to the physical DSP channel slot 1, dspm 5, dsp 4, dsp_channel 1.
Figure 30 shows that CSM has collected all the digits for dialing out.
May 16 12:22:27.580: CSM_PROC_OC3_COLLECT_ALL_DIGIT: CSM_EVENT_GET_ALL_DIGITS at slot 1, port 54
For PRI and for applications that do not require digit collection of outdialing digits (for example, voice calls), the intermediate digit collection states are skipped and the CSM state machine jumps to this state directly, pretending that the digit collection has been done.
Figure 31 shows an information message.
May 16 12:22:27.580: CSM_PROC_OC3_COLLECT_ALL_DIGIT: called party num: (30001) at slot 1, port 54
Figure 32 shows that CSM attempts to find a free signalling D channel to direct the outgoing call.
May 16 12:22:27.580: csm_vtsp_check_dchan (voice_vdev=0x60B8562C) May 16 12:22:27.580: csm_vtsp_check_dchan (vtsp requested dchan=0x60D7ACB0, dchan_idb=0x60E8ACF0) May 16 12:22:27.580: csm_vtsp_check_dchan (voice_vdev=0x60B8562C) May 16 12:22:27.580: csm_vtsp_check_dchan (vtsp requested dchan=0x60D7ACB0, dchan_idb=0x60D7ACB0)
In the case of voice calls, the free signalling D channel must match the voice interface specified inside the signalling data block (vtsp_sdb) passed from VTSP.
Figure 33 shows that CSM has received an event from ISDN.
May 16 12:22:27.624: EVENT_FROM_ISDN::dchan_idb=0x60D7ACB0, call_id=0xA121, ces=0x1 bchan=0x1E, event=0x3, cause=0x0
In this sample output:
Figure 34 shows that CSM has received a CALL PROCEEDING message from ISDN.
May 16 12:22:27.624: EVENT_FROM_ISDN:(A121): DEV_CALL_PROC at slot 1 and port 54
Figure 35 shows that the CALL PROCEEDING event received from ISDN has been interpreted as a CSM_EVENT_ISDN_BCHAN_ASSIGNED message.
*May 16 12:22:27.624: CSM_PROC_OC4_DIALING: CSM_EVENT_ISDN_BCHAN_ASSIGNED at slot 1, port 54
ISDN has assigned a B channel for this outgoing call. This B channel must be on the same PRI span as the signalling D channel we have allocated previously.
Figure 36 shows that the csm_vtsp_setup_for_oc function is called.
May 16 12:22:27.624: csm_vtsp_setup_for_oc (voice_vdev=0x60B8562C)
This is invoked when an outgoing call initiated by the VTSP receives a response from the ISDN stack.
Figure 37 shows that ISDN has sent a CONNECT message to CSM indicating that the call leg to the PSTN side has been established.
May 16 12:22:28.084: EVENT_FROM_ISDN::dchan_idb=0x60D7ACB0, call_id=0xA121, ces=0x1 bchan=0x1E, event=0x4, cause=0x0 May 16 12:22:28.084: EVENT_FROM_ISDN:(A121): DEV_CONNECTED at slot 1 and port 54
Figure 38 shows that while CSM is in the OC5_WAIT_FOR_CARRIER state, it has received the 'CONNECT' message from ISDN and has translated it into the CSM_EVENT_ISDN_CONNECTED message, which is passed to the CSM central state machine.
May 16 12:22:28.084: CSM_PROC_OC5_WAIT_FOR_CARRIER: CSM_EVENT_ISDN_CONNECTED at slot 1, port 54
Figure 39 shows that the function vtsp_confirm_oc() has been called.
May 16 12:22:28.084: vtsp_confirm_oc : (voice_vdev= 0x60B8562C)
This is invoked after CSM received the CONNECT from ISDN. CSM sends a confirmation of the CONNECT to VTSP.
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.
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.
Figure 40 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)
Figure 41 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)
Figure 42 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)
Figure 43 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)
Figure 44 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)
Figure 45 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)
Figure 46 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)
The debug vtsp all command enables the following debug vtsp commands: debug vtsp session, debug vtsp error, and debug vtsp dsp. For more information or sample output, refer to the individual commands in this chapter.
The debug vtsp dsp command shows messages from the DSP on the VFC to the router; this command can be useful if you suspect that the VFC is not functional. It is a simple way to check of the VFC is responding to off-hook indications.
Figure 47 shows the collection of DTMF digits from the DSP.
*Nov 30 00:44:34.491: vtsp_process_dsp_message: MSG_TX_DTMF_DIGIT: digit=3 *Nov 30 00:44:36.267: vtsp_process_dsp_message: MSG_TX_DTMF_DIGIT: digit=1 *Nov 30 00:44:36.571: vtsp_process_dsp_message: MSG_TX_DTMF_DIGIT: digit=0 *Nov 30 00:44:36.711: vtsp_process_dsp_message: MSG_TX_DTMF_DIGIT: digit=0 *Nov 30 00:44:37.147: vtsp_process_dsp_message: MSG_TX_DTMF_DIGIT: digit=2
The debug vtsp session command traces how the router interacts with the DSP based on the signalling indications from the signalling stack and requests from the application. This debug command displays information about how each network indication and application request is handled, signalling indications, and DSP control messages.
This debug level shows the internal workings of the voice telephony call state machine.
Figure 48 shows that the call has been accepted and that the system is now checking for incoming dial-peer matches.
Accept call and check for incoming dial-peer match:
*Nov 30 00:46:19.535: vtsp_tsp_call_accept_check (sdb=0x60CD4C58, calling_number=408 called_number=1): peer_tag=0 *Nov 30 00:46:19.535: vtsp_tsp_call_setup_ind (sdb=0x60CD4C58, tdm_info=0x60B80044, tsp_info=0x60B09EB0, calling_number=408 called_number=1): peer_tag=1
Figure 49 shows that a DSP has been allocated to handle the call and indicated the call to the higher layer code.
*Nov 30 00:46:19.535: vtsp_do_call_setup_ind: *Nov 30 00:46:19.535: dsp_open_voice_channel: [0:D:12] packet_len=12 channel_id=8737 packet_id=74 alaw_ulaw_select=0 transport_protocol=2 *Nov 30 00:46:19.535: dsp_set_playout_delay: [0:D:12] packet_len=18 channel_id=8737 packet_id=76 mode=1 initial=60 min=4 max=200 fax_nom=300 *Nov 30 00:46:19.535: dsp_echo_canceller_control: [0:D:12] packet_len=10 channel_id=8737 packet_id=66 flags=0x0 *Nov 30 00:46:19.539: dsp_set_gains: [0:D:12] packet_len=12 channel_id=8737 packet_id=91 in_gain=0 out_gain=0 *Nov 30 00:46:19.539: dsp_vad_enable: [0:D:12] packet_len=10 channel_id=8737 packet_id=78 thresh=-38 *Nov 30 00:46:19.559: vtsp_process_event: [0:D:12, 0.3, 13] act_setup_ind_ack
Figure 50 shows that the higher layer code has accepted the call, placed the DSP in DTMF mode, and collected digits.
*Nov 30 00:46:19.559: dsp_voice_mode: [0:D:12] packet_len=20 channel_id=8737 packet_id=73 coding_type=1 voice_field_size=160 VAD_flag=0 echo_length=64 comfort_noise=1 fax_detect=1 *Nov 30 00:46:19.559: dsp_dtmf_mode: [0:D:12] packet_len=10 channel_id=8737 packet_id=65 dtmf_or_mf=0 *Nov 30 00:46:19.559: dsp_cp_tone_on: [0:D:12] packet_len=30 channel_id=8737 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 *Nov 30 00:46:19.559: vtsp_timer: 278792 *Nov 30 00:46:22.059: vtsp_process_event: [0:D:12, 0.4, 25] act_dcollect_digit *Nov 30 00:46:22.059: dsp_cp_tone_off: [0:D:12] packet_len=8 channel_id=8737 packet_id=71 *Nov 30 00:46:22.059: vtsp_timer: 279042 *Nov 30 00:46:22.363: vtsp_process_event: [0:D:12, 0.4, 25] act_dcollect_digit *Nov 30 00:46:22.363: dsp_cp_tone_off: [0:D:12] packet_len=8 channel_id=8737 packet_id=71 *Nov 30 00:46:22.363: vtsp_timer: 279072 *Nov 30 00:46:22.639: vtsp_process_event: [0:D:12, 0.4, 25] act_dcollect_digit *Nov 30 00:46:22.639: dsp_cp_tone_off: [0:D:12] packet_len=8 channel_id=8737 packet_id=71 *Nov 30 00:46:22.639: vtsp_timer: 279100 *Nov 30 00:46:22.843: vtsp_process_event: [0:D:12, 0.4, 25] act_dcollect_digit *Nov 30 00:46:22.843: dsp_cp_tone_off: [0:D:12] packet_len=8 channel_id=8737 packet_id=71 *Nov 30 00:46:22.843: vtsp_timer: 279120 *Nov 30 00:46:23.663: vtsp_process_event: [0:D:12, 0.4, 25] act_dcollect_digit *Nov 30 00:46:23.663: dsp_cp_tone_off: [0:D:12] packet_len=8 channel_id=8737 packet_id=71 *Nov 30 00:46:23.663: vtsp_timer: 279202
Figure 51 shows that the call proceeded and that DTMF was disabled.
*Nov 30 00:46:23.663: vtsp_process_event: [0:D:12, 0.4, 15] act_dcollect_proc *Nov 30 00:46:23.663: dsp_cp_tone_off: [0:D:12] packet_len=8 channel_id=8737 packet_id=71 *Nov 30 00:46:23.663: dsp_idle_mode: [0:D:12] packet_len=8 channel_id=8737 packet_id=68
Figure 52 shows that the telephony call leg was conferenced with the packet network call leg and performed capabilities exchange with the network-side call leg.
*Nov 30 00:46:23.699: vtsp_process_event: [0:D:12, 0.5, 17] act_bridge *Nov 30 00:46:23.699: vtsp_process_event: [0:D:12, 0.5, 22] act_caps_ind *Nov 30 00:46:23.699: vtsp_process_event: [0:D:12, 0.5, 23] act_caps_ack Go into voice mode with codec indicated in caps exchange. *Nov 30 00:46:23.699: dsp_cp_tone_off: [0:D:12] packet_len=8 channel_id=8737 packet_id=71 *Nov 30 00:46:23.699: dsp_idle_mode: [0:D:12] packet_len=8 channel_id=8737 packet_id=68 *Nov 30 00:46:23.699: dsp_voice_mode: [0:D:12] packet_len=20 channel_id=8737 packet_id=73 coding_type=6 voice_field_size=20 VAD_flag=1 echo_length=64 comfort_noise=1 fax_detect=1
Figure 53 shows the call connected at remote side.
*Nov 30 00:46:23.779: vtsp_process_event: [0:D:12, 0.5, 10] act_connect
Figure 54 shows that disconnect was indicated, and passed to upper layers.
*Nov 30 00:46:30.267: vtsp_process_event: [0:D:12, 0.11, 5] act_generate_disc
Figure 55 shows that the conference was torn down and disconnect handshake completed.
*Nov 30 00:46:30.267: vtsp_process_event: [0:D:12, 0.11, 18] act_bdrop *Nov 30 00:46:30.267: dsp_cp_tone_off: [0:D:12] packet_len=8 channel_id=8737 packet_id=71 *Nov 30 00:46:30.267: vtsp_process_event: [0:D:12, 0.11, 20] act_disconnect *Nov 30 00:46:30.267: dsp_get_error_stat: [0:D:12] packet_len=10 channel_id=0 packet_id=6 reset_flag=1 *Nov 30 00:46:30.267: vtsp_timer: 279862
Figure 56 shows that the final DSP statistics were retrieved.
*Nov 30 00:46:30.275: vtsp_process_event: [0:D:12, 0.17, 30] act_get_error *Nov 30 00:46:30.275: 0:D:12: rx_dropped=0 tx_dropped=0 rx_control=353 tx_control=338 tx_control_dropped=0 dsp_mode_channel_1=2 dsp_mode_channel_2=0 c[0]=71 c[1]=71 c[2]=71 c[3]=71 c[4]=68 c[5]=71 c[6]=68 c[7]=73 c[8]=83 c[9]=84 c[10]=87 c[11]=83 c[12]=84 c[13]=87 c[14]=71 c[15]=6 *Nov 30 00:46:30.275: dsp_get_levels: [0:D:12] packet_len=8 channel_id=8737 packet_id=89 *Nov 30 00:46:30.279: vtsp_process_event: [0:D:12, 0.17, 34] act_get_levels *Nov 30 00:46:30.279: dsp_get_tx_stats: [0:D:12] packet_len=10 channel_id=8737 packet_id=86 reset_flag=1 *Nov 30 00:46:30.287: vtsp_process_event: [0:D:12, 0.17, 31] act_stats_complete *Nov 30 00:46:30.287: dsp_cp_tone_off: [0:D:12] packet_len=8 channel_id=8737 packet_id=71 *Nov 30 00:46:30.287: dsp_idle_mode: [0:D:12] packet_len=8 channel_id=8737 packet_id=68 *Nov 30 00:46:30.287: vtsp_timer: 279864
Figure 57 shows that the DSP channel was closed and released.
*Nov 30 00:46:30.287: vtsp_process_event: [0:D:12, 0.18, 6] act_wrelease_release *Nov 30 00:46:30.287: dsp_cp_tone_off: [0:D:12] packet_len=8 channel_id=8737 packet_id=71 *Nov 30 00:46:30.287: dsp_idle_mode: [0:D:12] packet_len=8 channel_id=8737 packet_id=68 *Nov 30 00:46:30.287: dsp_close_voice_channel: [0:D:12] packet_len=8 channel_id=8737 packet_id=75 *Nov 30 00:46:30.287: vtsp_process_event: [0:D:12, 0.16, 42] act_terminate
The debug vtsp session command generates a collection of DSP statistics for generating RTCP packets and a collection of other statistical information.
Figure 58 shows sample debug vtsp stats output.
*Nov 30 00:53:26.499: vtsp_process_event: [0:D:14, 0.11, 19] act_packet_stats *Nov 30 00:53:26.499: dsp_get_voice_playout_delay_stats: [0:D:14] packet_len=10 channel_id=8753 packet_id=83 reset_flag=0 *Nov 30 00:53:26.499: dsp_get_voice_playout_error_stats: [0:D:14] packet_len=10 channel_id=8753 packet_id=84 reset_flag=0 *Nov 30 00:53:26.499: dsp_get_rx_stats: [0:D:14] packet_len=10 channel_id=8753 packet_id=87 reset_flag=0 *Nov 30 00:53:26.503: vtsp_process_dsp_message: MSG_TX_GET_VOICE_PLAYOUT_DELAY: clock_offset=-1664482334 curr_rx_delay_estimate=69 low_water_mark_rx_delay=69 high_water_mark_rx_delay=70 *Nov 30 00:53:26.503: vtsp_process_event: [0:D:14, 0.11, 28] act_packet_stats_res *Nov 30 00:53:26.503: vtsp_process_dsp_message: MSG_TX_GET_VOICE_PLAYOUT_ERROR: predective_concelement_duration=0 interpolative_concelement_duration=0 silence_concelement_duration=0 retroactive_mem_update=0 buf_overflow_discard_duration=10 num_talkspurt_detection_errors=0 *Nov 30 00:53:26.503: vtsp_process_event: [0:D:14, 0.11, 29] act_packet_stats_res *Nov 30 00:53:26.503: vtsp_process_dsp_message: MSG_TX_GET_RX_STAT: num_rx_pkts=152 num_early_pkts=-2074277660 num_late_pkts=327892 num_signalling_pkts=0 num_comfort_noise_pkts=0 receive_durtation=3130 voice_receive_duration=2970 fax_receive_duration=0 num_pack_ooseq=0 num_bad_header=0 *Nov 30 00:53:26.503: vtsp_process_event: [0:D:14, 0.11, 32] act_packet_stats_res
For more information about Voice over IP (especially relating to differences in voice-port configuration) refer to the Cisco IOS 12.0 Voice, Video, and Home Applications Configuration Guide and Command Reference.
Posted: Wed Jun 23 18:21:03 PDT 1999
Copyright 1989-1999©Cisco Systems Inc.