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

Attention: The Community will be in read-only mode on 12/14/2017 from 12:00 am pacific to 11:30 am.

During this time you will only be able to see content. Other interactions such as posting, replying to questions, or marking content as helpful will be disabled for few hours.

We apologize for the inconvenience while we perform important updates to the Community.

New Member

VOIP delay

I initiated a conversation about same problem earlier with little confusion but now I have clear view about the situation.

TP---E1(R2analog)----3660----ethernet--1751 with FXS----TP

I picked 1751 attached telephone handset at 15:42:39.999 (40th sec) pressed digits 15:42:45.739 (45th sec)and got the ringback tone at 15:43:00.(next minuit).This took 15 seconds.

In the debug voip ccapi inoutoutput we can see nothing during 15:42:48.115 & 15:43:00.835 (12 sec) Can anyone help me to reduce this period ?

(Lots of debug lines are ommited because of the limitations of the post)

Apr 22 15:42:46.603: ssaDigit,1. callinfo.called , digit 11, callinfo.calling 6030, xrulecallingtag 0, xrulecalledtag 0

Apr 22 15:42:46.603: ssaDigit, 7. callinfo.calling 6030, sct->digit 11, result 1

Apr 22 15:42:47.139: cc_api_call_digit_begin (dstVdbPtr=0x0, dstCallId=0xFFFFFFFF, srcCallId=0x17,

digit=7, digit_begin_flags=0x1, rtp_timestamp=0xDE0760A4

rtp_expiration=0x0, dest_mask=0x1)

Apr 22 15:42:47.143: sess_appl: ev(10=CC_EV_CALL_DIGIT_BEGIN), cid(23), disp(0)

Apr 22 15:42:47.143: cid(23)st(SSA_CS_MAPPING)ev(SSA_EV_DIGIT_BEGIN)

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

Apr 22 15:42:47.143: ssaIgnore cid(23), st(SSA_CS_MAPPING),oldst(0), ev(10)

Apr 22 15:42:47.359: cc_api_call_digit_end (dstVdbPtr=0x0, dstCallId=0xFFFFFFFF, srcCallId=0x17,

digit=7,duration=255,xruleCallingTag=0,xruleCalledTag=0, dest_mask=0x1), digit_tone_mode=0

Apr 22 15:42:47.363: sess_appl: ev(9=CC_EV_CALL_DIGIT_END), cid(23), disp(0)

Apr 22 15:42:47.363: cid(23)st(SSA_CS_MAPPING)ev(SSA_EV_CALL_DIGIT)

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

Apr 22 15:42:47.363: ssaDigit

Apr 22 15:42:47.363: ssaDigit, 0. sct->digit 11, sct->digit len 2, usrDigit 7, digit_tone_mode=0

Apr 22 15:42:47.363: ssaDigit,1. callinfo.called , digit 117, callinfo.calling 6030, xrulecallingtag 0, xrulecalledtag 0

Apr 22 15:42:47.363: ssaDigit, 7. callinfo.calling 6030, sct->digit 117, result 1

Apr 22 15:42:47.819: cc_api_call_digit_begin (dstVdbPtr=0x0, dstCallId=0xFFFFFFFF, srcCallId=0x17,

digit=9, digit_begin_flags=0x1, rtp_timestamp=0xDE0760A4

rtp_expiration=0x0, dest_mask=0x1)

Apr 22 15:42:47.823: sess_appl: ev(10=CC_EV_CALL_DIGIT_BEGIN), cid(23), disp(0)

Apr 22 15:42:47.823: cid(23)st(SSA_CS_MAPPING)ev(SSA_EV_DIGIT_BEGIN)

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

Apr 22 15:42:47.823: ssaIgnore cid(23), st(SSA_CS_MAPPING),oldst(0), ev(10)

Apr 22 15:42:48.079: cc_api_call_digit_end (dstVdbPtr=0x0, dstCallId=0xFFFFFFFF, srcCallId=0x17,

digit=9,duration=295,xruleCallingTag=0,xruleCalledTag=0, dest_mask=0x1), digit_tone_mode=0

Apr 22 15:42:48.083: sess_appl: ev(9=CC_EV_CALL_DIGIT_END), cid(23), disp(0)

Apr 22 15:42:48.083: cid(23)st(SSA_CS_MAPPING)ev(SSA_EV_CALL_DIGIT)

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

Apr 22 15:42:48.083: ssaDigit

Apr 22 15:42:48.083: ssaDigit, 0. sct->digit 117, sct->digit len 3, usrDigit 9, digit_tone_mode=0

Apr 22 15:42:48.083: ssaDigit,1. callinfo.called , digit 1179, callinfo.calling 6030, xrulecallingtag 0, xrulecalledtag 0

Apr 22 15:42:48.083: ssaDigit, 7. callinfo.calling 6030, sct->digit 1179, result 0

Apr 22 15:42:48.083: ccCallReportDigits (callID=0x17, enable=0x0)

Apr 22 15:42:48.083: cc_api_call_report_digits_done (vdbPtr=0x8227F3A8, callID=0x17, disp=0)

Apr 22 15:42:48.083: ssaSetupPeer cid(23) peer list: tag(3) called number (1179)

Apr 22 15:42:48.087: ssaSetupPeer cid(23), destPat(1179), matched(1), prefix(), peer(822447E8), peer->encapType (2)

Apr 22 15:42:48.087: ccCallProceeding (callID=0x17, prog_ind=0x0)

Apr 22 15:42:48.087: ccCallSetupRequest (Inbound call = 0x17, outbound peer =3, dest=, params=0x8227AAC0 mode=0, *callID=0x8227AEF0, prog_ind = 3) callingIE_present 0

Apr 22 15:42:48.087: ccCallSetupRequest numbering_type 0x81

Apr 22 15:42:48.087: ccCallSetupRequest encapType 2 clid_restrict_disable 1 null_orig_clg 1 clid_transparent 0 callingNumber 6030

Apr 22 15:42:48.087: dest pattern 1..., called 1179, digit_strip 0

Apr 22 15:42:48.087: callingNumber=6030, calledNumber=1179, redirectNumber= display_info= calling_oct3a=0

Apr 22 15:42:48.087: accountNumber=, finalDestFlag=0,

guid=e241.9267.740f.11d7.8030.d508.fd9c.795d

Apr 22 15:42:48.087: peer_tag=3

Apr 22 15:42:48.087: ccIFCallSetupRequestPrivate: (vdbPtr=0x821884F4, dest=, callParams={called=1179,called_oct3=0x81, calling=6030,calling_oct3=0x0, calling_xlated=false, subscriber_type_str=RegularLine, fdest=0, voice_peer_tag=3},mode=0x0) vdbPtr type = 1

Apr 22 15:42:48.087: ccIFCallSetupRequestPrivate: (vdbPtr=0x821884F4, dest=, callParams={called=1179, called_oct3 0x81, calling=6030,calling_oct3 0x0, calling_xlated=false, fdest=0, voice_peer_tag=3}, mode=0x0, xltrc=-5)

Apr 22 15:42:48.091: cc_insert_call_entry: not incoming entry

Apr 22 15:42:48.091: cc_insert_call_entry: entry's incoming FALSE. is_incoming is FALSE

Apr 22 15:42:48.091: ccSaveDialpeerTag (callID=0x17, dialpeer_tag=0x3)

Apr 22 15:42:48.091: ccCallSetContext (callID=0x18, context=0x82457BDC)

Apr 22 15:42:48.091: sess_appl: ev(52=CC_EV_CALL_REPORT_DIGITS_DONE), cid(23), disp(0)

Apr 22 15:42:48.091: cid(23)st(SSA_CS_CALL_SETTING)ev(SSA_EV_CALL_REPORT_DIGITS_DONE)

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

Apr 22 15:42:48.091: -cid2(24)st2(SSA_CS_CALL_SETTING)oldst2(SSA_CS_MAPPING)

Apr 22 15:42:48.091: ssaReportDigitsDone cid(23) peer list: (empty)

Apr 22 15:42:48.091: ssaReportDigitsDone callid=23 Reporting disabled.

Apr 22 15:42:48.095: cc_api_supported_data data_mode=0x10002

Apr 22 15:42:48.095: ccTDUtilGetInstanceCount: For tagID[1] of callID[24]

Apr 22 15:42:48.099: ccTDPvtProfileTableObjectAccessManager: No profileTable set for callID[24]

Apr 22 15:42:48.099: ccTDUtilGetInstanceCount: For tagID[2] of callID[24]

Apr 22 15:42:48.099: ccTDPvtProfileTableObjectAccessManager: No profileTable set for callID[24]

Apr 22 15:42:48.103: cc_incr_if_call_volume: remote IP is 192.168.10.210

Apr 22 15:42:48.103: cc_incr_if_call_volume: hwidb is FastEthernet0/0

Apr 22 15:42:48.103: cc_incr_if_call_volume: create entry in list: 1

Apr 22 15:42:48.111: cc_api_call_proceeding(vdbPtr=0x821884F4, callID=0x18,

prog_ind=0x0, rawmsgPtr=0x0)

Apr 22 15:42:48.111: sess_appl: ev(21=CC_EV_CALL_PROCEEDING), cid(24), disp(0)

Apr 22 15:42:48.115: cid(24)st(SSA_CS_CALL_SETTING)ev(SSA_EV_CALL_PROCEEDING)

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

Apr 22 15:42:48.115: -cid2(23)st2(SSA_CS_CALL_SETTING)oldst2(SSA_CS_CALL_SETTING)

Apr 22 15:42:48.115: ssaCallProc

Apr 22 15:42:48.115: ccGetDialpeerTag (callID=0x17)

Apr 22 15:42:48.115: ssaIgnore cid(24), st(SSA_CS_CALL_SETTING),oldst(1), ev(21)

Apr 22 15:43:00.835: cc_api_call_alert(vdbPtr=0x821884F4, callID=0x18, prog_ind=0x8, sig_ind=0x1)

Apr 22 15:43:00.835: sess_appl: ev(7=CC_EV_CALL_ALERT), cid(24), disp(0)

Apr 22 15:43:00.835: cid(24)st(SSA_CS_CALL_SETTING)ev(SSA_EV_CALL_ALERT)

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

Apr 22 15:43:00.835: -cid2(23)st2(SSA_CS_CALL_SETTING)oldst2(SSA_CS_CALL_SETTING)

Apr 22 15:43:00.835: ssaAlert

Apr 22 15:43:00.835: ccGetDialpeerTag (callID=0x17)

Apr 22 15:43:00.835: ccCallAlert (callID=0x17, prog_ind=0x8, sig_ind=0x1)

Apr 22 15:43:00.835: ccConferenceCreate (confID=0x8227B364, callID1=0x17, callID2=0x18, tag=0x0)

Apr 22 15:43:00.835: cc_api_bridge_done (confID=0x5, srcIF=0x821884F4, srcCallID=0x18, dstCallID=0x17, disposition=0, tag=0x0)

Apr 22 15:43:00.839: cc_api_bridge_done (confID=0x5, srcIF=0x8227F3A8, srcCallID=0x17, dstCallID=0x18, disposition=0, tag=0x0)

Apr 22 15:43:00.839: cc_api_caps_ind (dstVdbPtr=0x821884F4, dstCallId=0x18, srcCallId=0x17,

caps={codec=0xFBFF, fax_rate=0xBF, vad=0x3, modem=0x2

codec_bytes=0, signal_type=3})

Apr 22 15:43:00.839: cc_api_caps_ind (Playout: mode 0, initial 60,min 40, max 300)

Apr 22 15:43:00.839: cc_api_caps_ind (dstVdbPtr=0x8227F3A8, dstCallId=0x17, srcCallId=0x18,

caps={codec=0x4, fax_rate=0x2, vad=0x2, modem=0x0

codec_bytes=20, signal_type=2})

Apr 22 15:43:00.839: cc_api_caps_ind (Playout: mode 0, initial 60,min 40, max 300)

Apr 22 15:43:00.839: cc_api_caps_ack (dstVdbPtr=0x8227F3A8, dstCallId=0x17, srcCallId=0x18,

caps={codec=0x4, fax_rate=0x2, vad=0x2, modem=0x0

codec_bytes=20, signal_type=2, seq_num_start=4683})

Apr 22 15:43:00.839: cc_api_caps_ack (dstVdbPtr=0x821884F4, dstCallId=0x18, srcCallId=0x17,

caps={codec=0x4, fax_rate=0x2, vad=0x2, modem=0x0

codec_bytes=20, signal_type=2, seq_num_start=4683})

Apr 22 15:43:00.843: cc_api_voice_mode_event , callID=0x17

Apr 22 15:43:00.843: Call Pointer =82457668

Apr 22 15:43:00.843: sess_appl: ev(29=CC_EV_CONF_CREATE_DONE), cid(23), disp(0)

Apr 22 15:43:00.843: cid(23)st(SSA_CS_CONFERENCING_ALERT)ev(SSA_EV_CONF_CREATE_DONE)

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

Apr 22 15:43:00.843: -cid2(24)st2(SSA_CS_CONFERENCING_ALERT)oldst2(SSA_CS_CALL_SETTING)

Apr 22 15:43:00.843: ssaConfCreateDoneAlert

Apr 22 15:43:00.843: sess_appl: ev(50=CC_EV_VOICE_MODE_DONE), cid(23), disp(0)

Apr 22 15:43:00.847: cid(23)st(SSA_CS_CONFERENCED_ALERT)ev(SSA_EV_VOICE_MODE_DONE)

oldst(SSA_CS_CONFERENCING_ALERT)cfid(5)csize(0)in(1)fDest(0)

Apr 22 15:43:00.847: -cid2(24)st2(SSA_CS_CONFERENCED_ALERT)oldst2(SSA_CS_CALL_SETTING)

Apr 22 15:43:00.847: ssaIgnore cid(23), st(SSA_CS_CONFERENCED_ALERT),oldst(4), ev(50)

Apr 22 15:43:00.847: cc_process_notify_bridge_done (event=0x8226B474)

Apr 22 15:43:05.519: cc_api_call_disconnected(vdbPtr=0x8227F3A8, callID=0x17, cause=0x10)

Apr 22 15:43:05.519: sess_appl: ev(11=CC_EV_CALL_DISCONNECTED), cid(23), disp(0)

Apr 22 15:43:05.519: cid(23)st(SSA_CS_CONFERENCED_ALERT)ev(SSA_EV_CALL_DISCONNECTED)

oldst(SSA_CS_CONFERENCED_ALERT)cfid(5)csize(0)in(1)fDest(0)

Apr 22 15:43:05.519: -cid2(24)st2(SSA_CS_CONFERENCED_ALERT)oldst2(SSA_CS_CALL_SETTING)

3 REPLIES
Cisco Employee

Re: VOIP delay

I assume that the debug collected is from 1751.

Call Alerting should be sent by the terminating gateway which is 3660. You you will see this line

Apr 22 15:43:00.835: cc_api_call_alert

after 1751 receive call alert from 3660. So we need to see the same debug like

debug vtsp all

debug ccapi inout

debug vpm all

from both the gateways to see why it take so long for 3660 to process that call.

Also need to see the config from 1751 and from 3600.

New Member

Re: VOIP delay

You are correct ; it is from 1751.

I was calling from the TP attached to the 1751.

3662 seize a channel from E1 to the PBX after this 12 seconds so we can assume the delay is in the 3662 proccesing part.

This does not happen when 1751 replaced by 1750.

(I can post only 10000 words at a time so I edited the configuration.)

3662 config

Busyout is not supported on this voice-port.

Busyout is not supported on this voice-port.

Busyout is not supported on this voice-port.

Busyout is not supported on this voice-port.

version 12.2

voice-card 4

voice call carrier capacity active

voice service pots

voice service voip

voice class codec 1

codec preference 1 g729r8

mta receive maximum-recipients 0

dial-peer voice 2 pots

destination-pattern ....

direct-inward-dial

port 4/0:1

forward-digits all

call rsvp-sync

voice-port 4/0:1

voice-port 4/1:1

mgcp profile default

dial-peer cor custom

dial-peer voice 6030 voip

destination-pattern 03.

session target ipv4:192.168.10.235

tech-prefix 6

alias exec d sh caller

!

!

end

1751 configuration

Building configuration...

Current configuration : 1060 bytes

!

version 12.2

service config

service timestamps debug datetime msec

service timestamps log uptime

no service password-encryption

!

hostname Router

!

enable secret xxxxxx

!

memory-size iomem 15

ip subnet-zero

!

!

!

!

voice call send-alert

voice rtp send-recv

!

voice class codec 1

codec preference 1 g729r8

!

!

!

!

!

!

!

!

!

interface FastEthernet0/0

ip address 192.168.10.235 255.255.255.0

speed auto

!

interface Serial0/0

no ip address

shutdown

!

interface Serial0/1

no ip address

shutdown

!

router rip

network 192.168.10.0

!

ip classless

no ip http server

ip pim bidir-enable

!

!

!

call rsvp-sync

!

voice-port 2/0

!

voice-port 2/1

!

dial-peer cor custom

!

!

!

dial-peer voice 1 pots

destination-pattern 6030

port 2/0

!

dial-peer voice 3 voip

destination-pattern 1...

voice-class codec 1

session target ipv4:192.168.10.210

!

dial-peer voice 4 voip

destination-pattern 6...

voice-class codec 1

session target ipv4:192.168.10.210

!

!

line con 0

line aux 0

line vty 0

password xxxx

login

line vty 1 4

login

!

end

New Member

Re: VOIP delay

Thanks....

Could solve by removing

call rsvp-sync in 3662 router...

181
Views
0
Helpful
3
Replies
CreatePlease to create content