Cisco Support Community
cancel
Showing results for 
Search instead for 
Did you mean: 
cancel
Community Member

VoIP debug analisys

Hi, I am in trouble with the following situation:

PABX A (E1, R2) -- (E1, R2) router (IP) -- Net -- (IP) router (E1, R2) -- (E1,R2) PABX (E&M) -- (E&M) tele (E&M) -- (E&M) PABX B.

When I make a call from A to B, it always gives busy.

Below the is a part of debug (debug vpm all, debug vtsp all), but I don't know the cause or who gave the disconnect, please some can help me ?

Mar 9 02:45:05.276: dsp_dtmf_dialing: [2/0:1 (2658)] packet_len=24 channel_id=2

packet_id=90 string=# digits=1, time_on=150, time_off=30

Mar 9 02:45:05.276: digit=^P, components=2, freq_of_first=0, freq_of_second=

0, amp_of_first=1, amp_of_second=1

Mar 9 02:45:05.344: vtsp_process_dsp_message: MSG_TX_DTMF_DIGIT_OFF: digit=1, d

uration=8246

Mar 9 02:45:05.344: vtsp:[2/0:1 (2658), S_R2_DIALING, E_DSP_DTMF_DIGIT]

Mar 9 02:45:05.344: dc_digit

Mar 9 02:45:05.344: htsp_digit_ready(2/0:1(10)): Rx digit='#'

Mar 9 02:45:05.344: R2 Outgoing Voice(2/0): DSX (E1 2/0:9): STATE: R2_OUT_PROCE

SS_A R2 Got Event R2_TONE_OFF

Mar 9 02:45:05.460: vtsp_process_dsp_message: MSG_TX_DIALING_DONE

Mar 9 02:45:05.460: vtsp:[2/0:1 (2658), S_R2_DIALING, E_DSP_DIALING_COMPLETE]dc

_dialing_done()

Mar 9 02:45:05.460: htsp_dialing_done(2/0:1(10))

Mar 9 02:45:06.752: vtsp:[2/0:1 (2658), S_R2_DIALING, E_CC_DISCONNECT]ds_dialin

g_release

Mar 9 02:45:06.752: dsp_idle_mode: [2/0:1 (2658)] packet_len=8 channel_id=2 pac

ket_id=68

Mar 9 02:45:06.752: act_setup_pend_dial_comp

Mar 9 02:45:06.752: dsp_idle_mode: [2/0:1 (2658)] packet_len=8 channel_id=2 pac

ket_id=68

Mar 9 02:45:06.752: act_disconnect

Mar 9 02:45:06.752: vtsp_ring_noan_timer_stop: 17685369

Mar 9 02:45:06.752: vtsp_pcm_tone_detect_timer_stop: 17685369

Mar 9 02:45:06.752: vtsp_pcm_switchover_timer_stop: 17685369

Mar 9 02:45:06.752: vtsp_cot_timer_stop: 17685369

Mar 9 02:45:06.752: vtsp_timer_stop: 17685369

Mar 9 02:45:06.752: vtsp_timer: 17685369

Mar 9 02:45:06.752: htsp_process_event: [2/0:1(10), R2_Q421_OG_SEIZE_ACK, E_DSP

_DIALING_DONE]

Mar 9 02:45:06.756: r2_q421_dial_done(2/0:1(10)) E_HTSP_RELEASE_REQ

Mar 9 02:45:06.756: r2_reg_dial_done(2/0:1(10))

Mar 9 02:45:06.764: vtsp:[2/0:1 (2658), S_WAIT_STATS, E_DSP_GET_ERROR]

Mar 9 02:45:06.764: act_get_error

Mar 9 02:45:06.764: 2/0:1 (2658): rx_dropped=0 tx_dropped=0 rx_control=37 tx_co

ntrol=20 tx_control_dropped=0 dsp_mode_channel_1=0 dsp_mode_channel_2=1 c[0]=90

c[1]=90 c[2]=90 c[3]=90 c[4]=90 c[5]=90 c[6]=90 c[7]=90 c[8]=90 c[9]=90 c[10]=90

c[11]=90 c[12]=90 c[13]=68 c[14]=68 c[15]=6

Mar 9 02:45:06.764: act_stats_complete

Mar 9 02:45:06.764: vtsp_timer_stop: 17685370

Mar 9 02:45:06.764: vtsp_ring_noan_timer_stop: 17685370

Mar 9 02:45:06.764: 2/0:1 (2658): rx_dropped=0 tx_dropped=0 rx_control=37 tx_co

ntrol=20 tx_control_dropped=0 dsp_mode_channel_1=0 dsp_mode_channel_2=1 c[0]=90

c[1]=90 c[2]=90 c[3]=90 c[4]=90 c[5]=90 c[6]=90 c[7]=90 c[8]=90 c[9]=90 c[10]=90

c[11]=90 c[12]=90 c[13]=68 c[14]=68 c[15]=6htsp_release_req: cause 16, no_onhoo

k 0

Mar 9 02:45:06.768: dsp_cp_tone_off: [2/0:1 (2658)] packet_len=8 channel_id=2 p

acket_id=71

Mar 9 02:45:06.768: dsp_idle_mode: [2/0:1 (2658)] packet_len=8 channel_id=2 pac

ket_id=68

Mar 9 02:45:06.768: vtsp_timer: 17685370

Mar 9 02:45:06.768: htsp_process_event: [2/0:1(10), R2_Q421_OG_SEIZE_ACK, E_HTS

P_RELEASE_REQ]

Mar 9 02:45:06.768: r2_q421_clr_fwd(2/0:1(10)) E_HTSP_RELEASE_REQ

Mar 9 02:45:06.768: r2_reg_channel_disconnected(2/0:1(10))

Mar 9 02:45:06.768: R2 Outgoing Voice(2/0): DSX (E1 2/0:9): STATE: R2_OUT_PROCE

SS_A R2 Got Event R2_STOP

Mar 9 02:45:06.768: r2_q421_clr_fwd(2/0:1(10)) Tx CLEAR FWD[R2 Q.421 2/0:1(10)]

set signal state = 0x8

Mar 9 02:45:06.768: htsp_timer - 1000 msec

Mar 9 02:45:06.768: r2_reg_process_event: [2/0:1(10), R2_REG_DIALING, E_R2_REG_

DISCONNECT(70)]

Mar 9 02:45:06.768: r2_reg_disconnect_dial(2/0:1(10))

Mar 9 02:45:06.768: r2_reg_timer_stop(2/0:1(10))

Thanks !!

Cleber

3 REPLIES
Cisco Employee

Re: VoIP debug analisys

There is something in the debugs that may help:

I don't know which router this debug is coming from, but we see the following:

Mar 9 02:45:05.344: htsp_digit_ready(2/0:1(10)): Rx digit='#'

Mar 9 02:45:05.344: R2 Outgoing Voice(2/0): DSX (E1 2/0:9): STATE: R2_OUT_PROCESS_A R2 Got Event R2_TONE_OFF

Mar 9 02:45:05.460: vtsp_process_dsp_message: MSG_TX_DIALING_DONE

Mar 9 02:45:05.460: vtsp:[2/0:1 (2658), S_R2_DIALING, E_DSP_DIALING_COMPLETE]dc_dialing_done()

Mar 9 02:45:05.460: htsp_dialing_done(2/0:1(10))

Mar 9 02:45:06.752: vtsp:[2/0:1 (2658), S_R2_DIALING, E_CC_DISCONNECT]ds_dialing_release

So, we see the "#" which is probably the digit string terminator, we complete dialing and then we get a disconnect on our telephony side, so the originating switch is disconnecting the call.

Mar 9 02:45:06.764: 2/0:1 (2658): rx_dropped=0 tx_dropped=0 rx_control=37 tx_control=20 tx_control_dropped=0 dsp_mode_channel_1=0 dsp_mode_channel_2=1 c[0]=90 c[1]=90 c[2]=90 c[3]=90 c[4]=90 c[5]=90 c[6]=90 c[7]=90 c[8]=90 c[9]=90 c[10]=90 c[11]=90 c[12]=90 c[13]=68 c[14]=68 c[15]=6htsp_release_req: cause 16, no_onhook 0

we see cause 16 which is normal call clearing.

You may have better luck with debugs like:

- debug voip ccapi inout

- debug cch323 session (for h.323)

- debug ccsip all (for SIP)

- debug mgcp packet (for MGCP)

in "debug voip ccapi inout" look for "cause="

But, right now it looks like the originating PABX is disconnecting.

What does the PABX say?

Regards,

Clay

Community Member

Re: VoIP debug analisys

Thanks, Clay !!

I got "debug voip ccapi inout " in the router connected to caller

PABX, the digits passed are OK. Below is the important part

of debug:

Mar 20 20:31:43.570: cc_api_call_setup_ind (vdbPtr=0x623993C8, callInfo={called=

8263610,called_oct3=0x81,calling=,calling_oct3=0x1,calling_oct3a=0x80,calling_xl

ated=false,subscriber_type_str=Unknown,fdest=1,peer_tag=830, prog_ind=3},callID=

0x626C196C)

Mar 20 20:31:43.570: cc_api_call_setup_ind sub_called oct3:len:data=0x0:104:

Mar 20 20:31:43.570: cc_api_call_setup_ind type 11 , prot 0

Mar 20 20:31:43.574: cc_process_call_setup_ind (event=0x623310C4)

Mar 20 20:31:43.574: >>>>CCAPI handed cid 16664 with tag 830 to app "DEFAULT"

Mar 20 20:31:43.574: sess_appl: ev(24=CC_EV_CALL_SETUP_IND), cid(16664), disp(0)

Mar 20 20:31:43.574: sess_appl: ev(SSA_EV_CALL_SETUP_IND), cid(16664), disp(0)

Mar 20 20:31:43.574: ssaCallSetupInd

Mar 20 20:31:43.574: ccCallSetContext (callID=0x4118, context=0x626AECF8)

Mar 20 20:31:43.574: ssaCallSetupInd cid(16664), st(SSA_CS_MAPPING),oldst(0), ev

(24)ev->e.evCallSetupInd.nCallInfo.finalDestFlag = 1

Mar 20 20:31:43.574: ssaCallSetupInd finalDest cllng(830....), clled(8263610)

Mar 20 20:31:43.574: ssaCallSetupInd cid(16664), st(SSA_CS_CALL_SETTING),oldst(0

), ev(24)dpMatchPeersMoreArg result= 0

Mar 20 20:31:43.578: ssaSetupPeer cid(16664) peer list: tag(820) called number

(8263610)

Mar 20 20:31:43.578: ssaSetupPeer cid(16664), destPat(8263610), matched(2), pref

ix(), peer(6260C740), peer->encapType (2)

Mar 20 20:31:43.578: ccCallProceeding (callID=0x4118, prog_ind=0x0)

Mar 20 20:31:43.578: ccCallSetupRequest (Inbound call = 0x4118, outbound peer =8

20, dest=,

params=0x6233EEF8 mode=0, *callID=0x6233F260, prog_ind = 3)

Mar 20 20:31:43.578: ccCallSetupRequest numbering_type 0x81

Mar 20 20:31:43.578: ccCallSetupRequest encapType 2 clid_restrict_disable 1 null

_orig_clg 1 clid_transparent 0 callingNumber 830....

Mar 20 20:31:43.578: dest pattern 82[0,1,2,3,5,6]...., called 8263610, digit_str

ip 0

Mar 20 20:31:43.578: callingNumber=830...., calledNumber=8263610, redirectNumber

= display_info= calling_oct3a=80

Mar 20 20:31:43.578: accountNumber=, finalDestFlag=1,

guid=bf9b.a333.2488.11cc.b9b2.9119.a5d3.20a0

Mar 20 20:31:43.578: peer_tag=820

Mar 20 20:31:43.578: ccIFCallSetupRequestPrivate: (vdbPtr=0x621BD500, dest=, cal

lParams={called=8263610,called_oct3=0x81, calling=830....,calling_oct3=0x1, call

ing_xlated=false, subscriber_type_str=Unknown, fdest=1, voice_peer_tag=820},mod

e=0x0) vdbPtr type = 1

Mar 20 20:31:43.578: sub_called oct3:len:data=0x0:104:

Mar 20 20:31:43.578: ccIFCallSetupRequestPrivate: (vdbPtr=0x621BD500, dest=, cal

lParams={called=8263610, called_oct3 0x81, calling=830....,calling_oct3 0x1, ca

lling_xlated=false, fdest=1, voice_peer_tag=820}, mode=0x0, xltrc=-5)

Mar 20 20:31:43.578: sub_called oct3:len:data=0x0:104:

Mar 20 20:31:43.582: ccSaveDialpeerTag (callID=0x4118, dialpeer_tag=0x334)

Mar 20 20:31:43.582: ccCallSetContext (callID=0x4119, context=0x626CE820)

Mar 20 20:31:43.582: ccCallReportDigits (callID=0x4118, enable=0x0)

Mar 20 20:31:43.582: cc_api_call_report_digits_done (vdbPtr=0x623993C8, callID=0

x4118, disp=0)

Mar 20 20:31:43.582: sess_appl: ev(52=CC_EV_CALL_REPORT_DIGITS_DONE), cid(16664)

, disp(0)

Mar 20 20:31:43.582: cid(16664)st(SSA_CS_CALL_SETTING)ev(SSA_EV_CALL_REPORT_DIGI

TS_DONE)

oldst(SSA_CS_MAPPING)cfid(-1)csize(0)in(1)fDest(1)

Mar 20 20:31:43.582: -cid2(16665)st2(SSA_CS_CALL_SETTING)oldst2(SSA_CS_MAPPING)

Mar 20 20:31:43.582: ssaReportDigitsDone cid(16664) peer list: (empty)

Mar 20 20:31:43.582: ssaReportDigitsDone callid=16664 Reporting disabled.

Mar 20 20:31:43.782: cc_api_call_proceeding(vdbPtr=0x621BD500, callID=0x4119,

prog_ind=0x0)

Mar 20 20:31:43.782: sess_appl: ev(21=CC_EV_CALL_PROCEEDING), cid(16665), disp(0

)

Mar 20 20:31:43.786: cid(16665)st(SSA_CS_CALL_SETTING)ev(SSA_EV_CALL_PROCEEDING)

oldst(SSA_CS_MAPPING)cfid(-1)csize(0)in(0)fDest(0)

Mar 20 20:31:43.786: -cid2(16664)st2(SSA_CS_CALL_SETTING)oldst2(SSA_CS_CALL_SETT

ING)

Mar 20 20:31:43.786: ssaCallProc

Mar 20 20:31:43.786: ccGetDialpeerTag (callID=0x4118)

Mar 20 20:31:43.786: ssaIgnore cid(16665), st(SSA_CS_CALL_SETTING),oldst(1), ev(

21)

Mar 20 20:31:47.626: cc_api_call_disconnected(vdbPtr=0x623993C8, callID=0x4118,

cause=0x10)

Mar 20 20:31:47.626: sess_appl: ev(11=CC_EV_CALL_DISCONNECTED), cid(16664), disp

(0)

Mar 20 20:31:47.626: cid(16664)st(SSA_CS_CALL_SETTING)ev(SSA_EV_CALL_DISCONNECTE

D)

oldst(SSA_CS_CALL_SETTING)cfid(-1)csize(0)in(1)fDest(1)

Mar 20 20:31:47.626: -cid2(16665)st2(SSA_CS_CALL_SETTING)oldst2(SSA_CS_CALL_SETT

ING)

Mar 20 20:31:47.626: ssaDiscSetting

Mar 20 20:31:47.626: ssaFlushPeerTagQueue cid(16664) peer list: (empty)

Mar 20 20:31:47.626: ssa: Disconnected cid(16664) state(1) cause(0x10)

Mar 20 20:31:47.626: ccCallDisconnect (callID=0x4118, cause=0x10 tag=0x0)

Mar 20 20:31:47.626: ccCallDisconnect (callID=0x4119, cause=0x10 tag=0x0)

Mar 20 20:31:47.726: cc_api_icpif: expect factor = 0

Mar 20 20:31:47.726: cc_api_call_disconnect_done(vdbPtr=0x621BD500, callID=0x411

9, disp=0, tag=0x0)

Mar 20 20:31:47.730: sess_appl: ev(12=CC_EV_CALL_DISCONNECT_DONE), cid(16665), d

isp(0)

Mar 20 20:31:47.730: cid(16665)st(SSA_CS_DISCONNECTING)ev(SSA_EV_CALL_DISCONNECT

_DONE)

oldst(SSA_CS_CALL_SETTING)cfid(-1)csize(0)in(0)fDest(0)

Mar 20 20:31:47.730: -cid2(16664)st2(SSA_CS_DISCONNECTING)oldst2(SSA_CS_CALL_SET

TING)

Mar 20 20:31:47.730: ssaDisconnectDone

Mar 20 20:31:49.626: cc_api_call_disconnect_done(vdbPtr=0x623993C8, callID=0x411

8, disp=0, tag=0x0)

Mar 20 20:31:49.626: sess_appl: ev(12=CC_EV_CALL_DISCONNECT_DONE), cid(16664), d

isp(0)

Mar 20 20:31:49.626: cid(16664)st(SSA_CS_DISCONNECTING)ev(SSA_EV_CALL_DISCONNECT

_DONE)

oldst(SSA_CS_CALL_SETTING)cfid(-1)csize(1)in(1)fDest(1)

Mar 20 20:31:49.626: ssaDisconnectDone

The cause was:

Mar 20 20:31:59.809: ccCallDisconnect (callID=0x40EE, cause=0x10 tag=0x0)

Please, do you know what this cause is ? And is this PABX, that is the initiator, the generator of disconnect ?

Thanks,

Cleber

Ps.: it is very difficul to find any document abot theses debugs.

Cisco Employee

Re: VoIP debug analisys

Hi Cleber -

The cause codes can be confusing. In this case we see that the cause code is 0x10, which is decimal 16. These translate to "normal call clearing".

Mar 20 20:31:43.786: ccGetDialpeerTag (callID=0x4118)

Mar 20 20:31:43.786: ssaIgnore cid(16665), st(SSA_CS_CALL_SETTING)oldst(1), ev(21)

Mar 20 20:31:47.626: cc_api_call_disconnected(vdbPtr=0x623993C8, callID=0x4118, cause=0x10)

Mar 20 20:31:47.626: sess_appl: ev(11=CC_EV_CALL_DISCONNECTED), cid(16664), disp (0)

We see that after a 4 second delay we receive cc_api_call_disconnected. This tells us that it was the remote side that disconnected the call (cc_api_xxx messages tell us about the VoIP leg of the call).

If we had seen ccCallDisconnect first, that would have told us the disconnect was initiated by the POTS side.

It appears in this case that it is the remote PBX that is disconnecting the call.

Here are some links for troubleshooting:

E1 R2:

http://www.cisco.com/en/US/partner/tech/tk652/tk653/technologies_configuration_example09186a00800ad389.shtml#proc

debug voip ccapi:

http://www.cisco.com/en/US/partner/tech/tk652/tk701/technologies_tech_note09186a0080094045.shtml

Regards,

Clay

380
Views
3
Helpful
3
Replies
CreatePlease to create content