VoIPコールのトラブルシューティングとデバッグ

router# show controllers T1 1/0
T1 1/0 is up.
Applique type is Channelized T1
Cablelength is short 133
No alarms detected.
Framing is ESF, Line Code is B8ZS, Clock Source is Line
Primary.
Data in current interval (6 seconds elapsed):

	0 Line Code Violations, 0 Path Code Violations
	0 Slip Secs, 0 Fr Loss Secs, 0 Line Err Secs, 
  0 Degraded Mins
	0 Errored Secs, 0 Bursty Err Secs, 0 Severely Err Secs,
  0 Unavail Secs

router# show voice port 1/0:1
recEive and transMit Slot is 1, Sub-unit is 0, Port is 1
Type of VoicePort is E&M 
Operation State is DORMANT
Administrative State is UP
No Interface Down Failure
Description is not set
Noise Regeneration is enabled
Non Linear Processing is enabled
Music On Hold Threshold is Set to -38 dBm
In Gain is Set to 0 dB
Out Attenuation is Set to 0 dB
Echo Cancellation is enabled
Echo Cancel Coverage is set to 16 ms
Connection Mode is normal
Connection Number is not set
Initial Time Out is set to 10 s
Interdigit Time Out is set to 10 s
Call-Disconnect Time Out is set to 60 s
Region Tone is set for US

Voice card specific Info Follows:
Out Attenuation is Set to 0 dB
Echo Cancellation is enabled
Echo Cancel Coverage is set to 16 ms
Connection Mode is normal (could be trunk or plar)
Connection Number is not set
Initial Time Out is set to 10 s
Interdigit Time Out is set to 10 s
Call-Disconnect Time Out is set to 60 s
Region Tone is set for US

Voice card specific Info Follows:
Signal Type is wink-start
Operation Type is 2-wire
E&M Type is 1
Dial Type is dtmf
In Seizure is inactive
Out Seizure is inactive
Digit Duration Timing is set to 100 ms

InterDigit Duration Timing is set to 100 ms
Pulse Rate Timing is set to 10 pulses/second
InterDigit Pulse Duration Timing is set to 500 ms
Clear Wait Duration Timing is set to 400 ms
Wink Wait Duration Timing is set to 200 ms
Wink Duration Timing is set to 200 ms
Delay Start Timing is set to 300 ms
Delay Duration Timing is set to 2000 ms
Dial Pulse Min. Delay is set to 140 ms

maui-voip-austin#debug vpm signal


!--- FXS port 1/0/0 goes from the "on-hook" to "off-hook" !--- state.

htsp_process_event: [1/0/0, 1.2 , 36] 
fxsls_onhook_offhook htsp_setup_ind
*Mar 10 16:08:55.958: htsp_process_event: 
[1/0/0, 1.3 , 8] 


!--- Sends ringing alert to the called phone.

*Mar 10 16:09:02.410: htsp_process_event: 
[1/0/0, 1.3 , 10] htsp_alert_notify
*Mar 10 16:09:03.378: htsp_process_event: 
[1/0/0, 1.3 , 11] 


!--- End of phone call, port goes "on-hook".

*Mar 10 16:09:11.966: htsp_process_event: 
[1/0/0, 1.3 , 6] 
*Mar 10 16:09:17.218: htsp_process_event: 
[1/0/0, 1.3 , 28] fxsls_offhook_onhook
*Mar 10 16:09:17.370: htsp_process_event: 
[1/0/0, 1.3 , 41] fxsls_offhook_timer
*Mar 10 16:09:17.382: htsp_process_event: 
[1/0/0, 1.2 , 7] fxsls_onhook_release

maui-voip-austin#debug vpm spi   
Voice Port Module Session debugging is enabled


!--- The DSP is put into digit collection mode.

*Mar 10 16:48:55.710: dsp_digit_collect_on: 
[1/0/0] packet_len=20 channel_id=128
 packet_id=35 min_inter_delay=290 
 max_inter_delay=3200 mim_make_time=18 max_make
_time=75 min_brake_time=18 max_brake_time=75

maui-voip-austin#show dialplan number 5000
Dial string terminator: #
Macro Exp.: 5000

VoiceOverIpPeer2
        information type = voice,
        tag = 2, destination-pattern = `5000',
        answer-address = `', preference=0,
        group = 2, Admin state is up, Operation
        state is up,
        incoming called-number = `', 
        connections/maximum = 0/unlimited,
        application associated: 
        type = voip, session-target = 
        `ipv4:192.168.10.2',
        technology prefix: 
        ip precedence = 5, UDP checksum = 
        disabled, session-protocol = cisco, 
        req-qos = best-effort, 
        acc-qos = best-effort, 
        dtmf-relay = cisco-rtp, 
        fax-rate = voice,   
        payload size =  20 bytes
        codec = g729r8,   
        payload size =  20 bytes,
        Expect factor = 10, Icpif = 30,
        signaling-type = cas,
        VAD = enabled, Poor QOV Trap = disabled, 
        Connect Time = 25630, Charged Units = 0,
        Successful Calls = 25, Failed Calls = 0,
        Accepted Calls = 25, Refused Calls = 0,
        Last Disconnect Cause is "10  ",
        Last Disconnect Text is "normal call 
        clearing.",
        Last Setup Time = 84427934.
        Matched: 5000   Digits: 4
        Target: ipv4:192.168.10.2

maui-voip-austin#debug vtsp session 
Voice telephony call control session debugging is on


!--- Output is suppressed. 
!--- ACTION: Caller picked up handset. 
!--- The DSP is allocated, jitter buffers, VAD 
!--- thresholds, and signal levels are set.


*Mar 10 18:14:22.865: dsp_set_playout: [1/0/0 (69)]
packet_len=18 channel_id=1 packet_id=76 mode=1 
initial=60 min=4 max=200 fax_nom=300
*Mar 10 18:14:22.865: dsp_echo_canceller_control: 
[1/0/0 (69)] packet_len=10 channel_id=1 packet_id=66
flags=0x0
*Mar 10 18:14:22.865: dsp_set_gains: [1/0/0 (69)] 
packet_len=12 channel_id=1 packet_id=91 
in_gain=0 out_gain=65506
*Mar 10 18:14:22.865: dsp_vad_enable: [1/0/0 (69)] 
packet_len=10 channel_id=1 packet_id=78 
thresh=-38act_setup_ind_ack 
*Mar 10 18:14:22.869: dsp_voice_mode: [1/0/0 (69)] 
packet_len=24 channel_id=1 packet_id=73 coding_type=1
 voice_field_size=80 
VAD_flag=0 echo_length=64 comfort_noise=1 
inband_detect=1 digit_relay=2 
AGC_flag=0act_setup_ind_ack(): dsp_dtmf_mod
e()act_setup_ind_ack: passthru_mode = 0, 
no_auto_switchover = 0dsp_dtmf_mode
(VTSP_TONE_DTMF_MODE)


!--- The DSP is put into "voice mode" and dial-tone is 
!--- generated.


*Mar 10 18:14:22.873: dsp_cp_tone_on: [1/0/0 (69)] 
packet_len=30 channel_id=1 packet_id=72 tone_id=4 
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

!--- Action: A VoIP call is originated through the 
!--- Telephony SPI (pots leg) to extension 5000. 
!--- Some output is omitted.


maui-voip-austin#debug voip ccapi inout
voip ccAPI function enter/exit debugging is on


!--- Call leg identification, source peer: Call 
!--- originated from dial-peer 1 pots 
!--- (extension 4000).


*Mar 15 22:07:11.959: cc_api_call_setup_ind 
(vdbPtr=0x81B09EFC, callInfo={called=, 
calling=4000, fdest=0 peer_tag=1}, callID=0x81B628F0)

!--- CCAPI invokes the session application.


*Mar 15 22:07:11.963: cc_process_call_setup_ind
(event=0x81B67E44) handed call to app "SESSION"
*Mar 15 22:07:11.963: sess_appl: 
ev(23=CC_EV_CALL_SETUP_IND), cid(88), disp(0)


!--- Allocate call leg identifiers "callid = 0x59"


*Mar 15 22:07:11.963: ccCallSetContext 
(callID=0x58, context=0x81BAF154)
*Mar 15 22:07:11.963: ccCallSetupAck 
(callID=0x58)


!--- Instruct VTSP to generate dialtone
. 

*Mar 15 22:07:11.963: ccGenerateTone 
(callID=0x58 tone=8)


!--- VTSP passes digits to CCAPI.


*Mar 15 22:07:20.275:cc_api_call_digit_begin
(vdbPtr=0x81B09EFC,callID=0x58,digit=5, flags=0x1, timestamp=0xC2E63BB7, expiration=0x0)
*Mar 15 22:07:20.279: sess_appl: 
ev(10=CC_EV_CALL_DIGIT_BEGIN), cid(88), disp(0)
*Mar 15 22:07:20.279: ssaTraceSct: 
cid(88)st(0)oldst(0)cfid(-1)csize(0)in(1)fDest(0)
*Mar 15 22:07:20.279: ssaIgnore cid(88), 
st(0),oldst(0), ev(10)
*Mar 15 22:07:20.327: cc_api_call_digit 
(vdbPtr=0x81B09EFC, callID=0x58, digit=5
, duration=100)
*Mar 15 22:07:20.327: sess_appl: 
ev(9=CC_EV_CALL_DIGIT), cid(88), disp(0)
*Mar 15 22:07:20.327: ssaTraceSct: 
cid(88)st(0)oldst(0)cfid(-1)csize(0)in(1)fDes
t(0)
*Mar 15 22:07:21.975:cc_api_call_digit_begin
(vdbPtr=0x81B09EFC,callID=0x58,digit=0, 
flags=0x1, timestamp=0xC2E63BB7, expiration=0x0)
*Mar 15 22:07:21.979: sess_appl: 
ev(10=CC_EV_CALL_DIGIT_BEGIN), cid(88), disp(0)
*Mar 15 22:07:21.979: ssaTraceSct: 
cid(88)st(0)oldst(0)cfid(-1)csize(0)in(1)fDes
t(0)
*Mar 15 22:07:21.979: ssaIgnore cid(88), 
st(0),oldst(0), ev(10)
*Mar 15 22:07:22.075: cc_api_call_digit 
(vdbPtr=0x81B09EFC, callID=0x58, digit=0
, duration=150)
*Mar 15 22:07:22.079: sess_appl: 
ev(9=CC_EV_CALL_DIGIT), cid(88), disp(0)
*Mar 15 22:07:22.079: ssaTraceSct: 
cid(88)st(0)oldst(0)cfid(-1)csize(0)in(1)fDest(0)
*Mar 15 22:07:23.235: cc_api_call_digit_begin
(vdbPtr=0x81B09EFC, callID=0x58, dgit=0, 
flags=0x1, timestamp=0xC2E63BB7, expiration=0x0)
*Mar 15 22:07:23.239: sess_appl: 
ev(10=CC_EV_CALL_DIGIT_BEGIN), cid(88), disp(0)
*Mar 15 22:07:23.239: ssaTraceSct: 
cid(88)st(0)oldst(0)cfid(-1)csize(0)in(1)fDest(0)
*Mar 15 22:07:23.239: ssaIgnore cid(88), 
st(0),oldst(0), ev(10)
*Mar 15 22:07:23.335: cc_api_call_digit 
(vdbPtr=0x81B09EFC, callID=0x58, digit=0
, duration=150)
*Mar 15 22:07:23.339: sess_appl: 
ev(9=CC_EV_CALL_DIGIT), cid(88), disp(0)
*Mar 15 22:07:23.339: ssaTraceSct: 
cid(88)st(0)oldst(0)cfid(-1)csize(0)in(1)fDes
t(0)
*Mar 15 22:07:25.147: cc_api_call_digit_begin
(vdbPtr=0x81B09EFC, callID=0x58, d
igit=0, flags=0x1, timestamp=0xC2E63BB7, 
expiration=0x0)
*Mar 15 22:07:25.147: sess_appl: 
ev(10=CC_EV_CALL_DIGIT_BEGIN), cid(88), disp(0)
*Mar 15 22:07:25.147: ssaTraceSct: 
cid(88)st(0)oldst(0)cfid(-1)csize(0)in(1)fDest(0)
*Mar 15 22:07:25.147: ssaIgnore cid(88), 
st(0),oldst(0), ev(10)
*Mar 15 22:07:25.255: cc_api_call_digit 
(vdbPtr=0x81B09EFC, callID=0x58, digit=0
, duration=160)
*Mar 15 22:07:25.259: sess_appl: 
ev(9=CC_EV_CALL_DIGIT), cid(88), disp(0)
*Mar 15 22:07:25.259: ssaTraceSct: 
cid(88)st(0)oldst(0)cfid(-1)csize(0)in(1)fDest(0)


!--- Matched dial-peer 2 voip. Destination number !--- 5000


*Mar 15 22:07:25.259: ssaSetupPeer cid(88) 
peer list:tag(2) called number(5000) 
*Mar 15 22:07:25.259: ssaSetupPeer cid(88), 
destPat(5000), matched(4), prefix(),
peer(81C04A10)


!--- Continue to call an interface and start the !--- next call leg.


*Mar 15 22:07:25.259: ccCallProceeding 
(callID=0x58, prog_ind=0x0)
*Mar 15 22:07:25.259: ccCallSetupRequest 
(Inbound call = 0x58, outbound peer =2,
dest=, params=0x81BAF168 mode=0, 
*callID=0x81B6DE58)
*Mar 15 22:07:25.259: callingNumber=4000, 
calledNumber=5000, redirectNumber=


!--- VoIP call setup.


*Mar 15 22:07:25.263: ccIFCallSetupRequest:
(vdbPtr=0x81A75558, dest=, 
callParams={called=5000, calling=4000,
fdest=0, voice_peer_tag=2}, mode=0x0)
*Mar 15 22:07:25.263: ccCallSetContext 
(callID=0x59, context=0x81BAF3E4)
*Mar 15 22:07:25.375: ccCallAlert 
(callID=0x58, prog_ind=0x8, sig_ind=0x1)


!--- POTS and VoIP call legs are tied together.


*Mar 15 22:07:25.375: ccConferenceCreate 
(confID=0x81B6DEA0, callID1=0x58, callI
D2=0x59, tag=0x0)
*Mar 15 22:07:25.375: cc_api_bridge_done 
(confID=0x1E, srcIF=0x81B09EFC, srcCall
ID=0x58, dstCallID=0x59, disposition=0, 
tag=0x0)


!--- Exchange capability bitmasks with remote 
!--- the VoIP gateway 
!--- (Codec, VAD, VoIP or FAX, FAX-rate, and so forth).


*Mar 15 22:07:26.127: cc_api_caps_ind 
(dstVdbPtr=0x81B09EFC, dstCallId=0x58, src
CallId=0x59,caps={codec=0x4, fax_rate=0x2, 
vad=0x2, modem=0x1 codec_bytes=20, 
signal_type=0})


!--- Both gateways agree on capabilities.

*Mar 15 22:07:26.127: cc_api_caps_ack 
(dstVdbPtr=0x81B09EFC, dstCallId=0x58, src
CallId=0x59, caps={codec=0x4, fax_rate=0x2, 
vad=0x2, modem=0x1 codec_bytes=20,
signal_type=0})
*Mar 15 22:07:26.139: cc_api_caps_ack 
(dstVdbPtr=0x81A75558, dstCallId=0x59, src
CallId=0x58, caps={codec=0x4, fax_rate=0x2, 
vad=0x2, modem=0x1 codec_bytes=20,
signal_type=0})
*Mar 15 22:07:35.259: cc_api_call_digit 
(vdbPtr=0x81B09EFC, callID=0x58, digit=T
, duration=0)
*Mar 15 22:07:35.259: sess_appl: 
ev(9=CC_EV_CALL_DIGIT), cid(88), disp(0)
*Mar 15 22:07:35.259: ssaTraceSct: 
cid(88)st(4)oldst(3)cfid(30)csize(0)in(1)
fDest(0)-cid2(89)st2(4)oldst2(1)
*Mar 15 22:07:35.399: cc_api_call_connected
(vdbPtr=0x81A75558, callID=0x59)
*Mar 15 22:07:35.399: sess_appl: 
ev(8=CC_EV_CALL_CONNECTED), cid(89), disp(0)
*Mar 15 22:07:35.399: ssaTraceSct: 
cid(89)st(4)oldst(1)cfid(30)csize(0)in(0)
fDest(0)-cid2(88)st2(4)oldst2(4)


!--- VoIP call is connected.


*Mar 15 22:07:35.399: ccCallConnect 
(callID=0x58)


!--- VoIP call is disconnected. Cause = 0x10
 

*Mar 15 23:29:39.530: ccCallDisconnect 
(callID=0x5B, cause=0x10 tag=0x0)