Delay in outbound & inbound calls

Asterisk Asterisk Support
1

I have an issue with outgoing calls and inbound calls on elastix 2.6 some time i can make calls from ipphoe but its take more than 10 to 25 seconds Or cannot make calls
Incoming
Some time phone is ringing no voice or delay but some time its okay but take too long time for call routing

Elastix Version 2.4.0 asterix 11.13 Freepbx 2.11.0

CLI Output

*-- Executing [s@macro-dialout-trunk:21] GotoIf(“SIP/143-00000090”, “0?customtrunk”) in new stack

– Executing [s@macro-dialout-trunk:22] Dial(“SIP/143-00000090”, “DAHDI/g0/0558726480,300,”) in new stack
– Called DAHDI/g0/0558726480

– DAHDI/1-1 answered SIP/143-00000090

– 0x2abb7c05aa20 – Probation passed - setting RTP source address to 172.14.5.203:58064

– Remote UNIX connection

– Remote UNIX connection disconnected*
"

Then after 20 second line is connected some time not conecting

Live Log tail -f full output

new stack [2016-07-03 17:27:01] VERBOSE[5360][C-00000060] pbx.c: – Executing [s@macro-dialout-trunk:21] GotoIf(“SIP/143-00000091”, “0?customtrunk”) in new stack

[2016-07-03 17:27:01] VERBOSE[5360][C-00000060] pbx.c: – Executing [s@macro-dialout-trunk:22] Dial(“SIP/143-00000091”, “DAHDI/g0/0558726480,300,”) in new stack

[2016-07-03 17:27:01] VERBOSE[5360][C-00000060] app_dial.c: – Called DAHDI/g0/0558726480

[2016-07-03 17:27:06] VERBOSE[5360][C-00000060] app_dial.c: – DAHDI/1-1 answered SIP/143-00000091

But SIP Trunk is working perfectly …

2

When you watch in real time, is the delay before or after the Goto?

Goto should be fast. Whilst I thought the timestamp should reflect when the log is written, it is just possible it reflects when the parse on the line started, an there is something in the expression that evaluates to false, that is taking a long time (database lookup?). As you didn’t supply the expression, I suspect this is a question for the FreePBX people.

3

Hi david ,
Thank for your replay …
can you please check the full logs …

[2016-07-05 10:47:45] VERBOSE[6379][C-00000020] netsock2.c: == Using SIP RTP TOS bits 184
[2016-07-05 10:47:45] VERBOSE[6379][C-00000020] netsock2.c: == Using SIP RTP CoS mark 5
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [0558726480@from-internal:1] Macro(“SIP/143-00000024”, “user-callerid,LIMIT,EXTERNAL,”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-user-callerid:1] Set(“SIP/143-00000024”, “TOUCH_MONITOR=1467701265.60”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-user-callerid:2] Set(“SIP/143-00000024”, “AMPUSER=143”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-user-callerid:3] GotoIf(“SIP/143-00000024”, “0?report”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-user-callerid:4] ExecIf(“SIP/143-00000024”, “1?Set(REALCALLERIDNUM=143)”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-user-callerid:5] Set(“SIP/143-00000024”, “AMPUSER=143”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-user-callerid:6] GotoIf(“SIP/143-00000024”, “0?limit”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-user-callerid:7] Set(“SIP/143-00000024”, “AMPUSERCIDNAME=JOBISH”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-user-callerid:8] GotoIf(“SIP/143-00000024”, “0?report”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-user-callerid:9] Set(“SIP/143-00000024”, “AMPUSERCID=143”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-user-callerid:10] Set(“SIP/143-00000024”, “__DIAL_OPTIONS=tr”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-user-callerid:11] Set(“SIP/143-00000024”, “CALLERID(all)=“JOBISH” <143>”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-user-callerid:12] GotoIf(“SIP/143-00000024”, “0?limit”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-user-callerid:13] ExecIf(“SIP/143-00000024”, “1?Set(GROUP(concurrency_limit)=143)”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-user-callerid:14] ExecIf(“SIP/143-00000024”, “0?Set(CHANNEL(language)=)”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-user-callerid:15] GotoIf(“SIP/143-00000024”, “1?continue”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Goto (macro-user-callerid,s,28)
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-user-callerid:28] Set(“SIP/143-00000024”, “CALLERID(number)=143”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-user-callerid:29] Set(“SIP/143-00000024”, “CALLERID(name)=JOBISH”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-user-callerid:30] Set(“SIP/143-00000024”, “CDR(cnum)=143”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-user-callerid:31] Set(“SIP/143-00000024”, “CDR(cnam)=JOBISH”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-user-callerid:32] Set(“SIP/143-00000024”, “CHANNEL(language)=en”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [0558726480@from-internal:2] Set(“SIP/143-00000024”, “MOHCLASS=default”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [0558726480@from-internal:3] Set(“SIP/143-00000024”, “_NODEST=”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [0558726480@from-internal:4] Gosub(“SIP/143-00000024”, “sub-record-check,s,1(out,0558726480,)”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@sub-record-check:1] Set(“SIP/143-00000024”, “REC_POLICY_MODE_SAVE=”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@sub-record-check:2] GotoIf(“SIP/143-00000024”, “1?check”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Goto (sub-record-check,s,7)
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@sub-record-check:7] Set(“SIP/143-00000024”, “__MON_FMT=wav”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@sub-record-check:8] GotoIf(“SIP/143-00000024”, “1?next”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Goto (sub-record-check,s,11)
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@sub-record-check:11] ExecIf(“SIP/143-00000024”, “0?Return()”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@sub-record-check:12] ExecIf(“SIP/143-00000024”, “0?Set(__REC_POLICY_MODE=)”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@sub-record-check:13] GotoIf(“SIP/143-00000024”, “0?out,1”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@sub-record-check:14] Set(“SIP/143-00000024”, “__REC_STATUS=INITIALIZED”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@sub-record-check:15] Set(“SIP/143-00000024”, “NOW=1467701265”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@sub-record-check:16] Set(“SIP/143-00000024”, “__DAY=05”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@sub-record-check:17] Set(“SIP/143-00000024”, “__MONTH=07”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@sub-record-check:18] Set(“SIP/143-00000024”, “__YEAR=2016”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@sub-record-check:19] Set(“SIP/143-00000024”, “__TIMESTR=20160705-104745”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@sub-record-check:20] Set(“SIP/143-00000024”, “__FROMEXTEN=143”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@sub-record-check:21] Set(“SIP/143-00000024”, “__CALLFILENAME=out-0558726480-143-20160705-104745-1467701265.60”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@sub-record-check:22] Goto(“SIP/143-00000024”, “out,1”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Goto (sub-record-check,out,1)
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [out@sub-record-check:1] ExecIf(“SIP/143-00000024”, “1?Set(__REC_POLICY_MODE=dontcare)”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [out@sub-record-check:2] GosubIf(“SIP/143-00000024”, “0?record,1(exten,0558726480,143)”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [out@sub-record-check:3] Return(“SIP/143-00000024”, “”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [0558726480@from-internal:5] Macro(“SIP/143-00000024”, “dialout-trunk,1,0558726480,off”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-dialout-trunk:1] Set(“SIP/143-00000024”, “DIAL_TRUNK=1”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-dialout-trunk:2] GosubIf(“SIP/143-00000024”, “0?sub-pincheck,s,1()”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-dialout-trunk:3] GotoIf(“SIP/143-00000024”, “0?disabletrunk,1”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-dialout-trunk:4] Set(“SIP/143-00000024”, “DIAL_NUMBER=0558726480”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-dialout-trunk:5] Set(“SIP/143-00000024”, “DIAL_TRUNK_OPTIONS=tr”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-dialout-trunk:6] Set(“SIP/143-00000024”, “OUTBOUND_GROUP=OUT_1”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-dialout-trunk:7] GotoIf(“SIP/143-00000024”, “1?nomax”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Goto (macro-dialout-trunk,s,9)
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-dialout-trunk:9] GotoIf(“SIP/143-00000024”, “0?skipoutcid”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-dialout-trunk:10] Set(“SIP/143-00000024”, “DIAL_TRUNK_OPTIONS=”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-dialout-trunk:11] Macro(“SIP/143-00000024”, “outbound-callerid,1”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-outbound-callerid:1] ExecIf(“SIP/143-00000024”, “0?Set(CALLERPRES()=)”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-outbound-callerid:2] ExecIf(“SIP/143-00000024”, “0?Set(REALCALLERIDNUM=143)”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-outbound-callerid:3] GotoIf(“SIP/143-00000024”, “1?normcid”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Goto (macro-outbound-callerid,s,6)
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-outbound-callerid:6] Set(“SIP/143-00000024”, “USEROUTCID=”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-outbound-callerid:7] Set(“SIP/143-00000024”, “EMERGENCYCID=”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-outbound-callerid:8] Set(“SIP/143-00000024”, “TRUNKOUTCID=”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-outbound-callerid:9] GotoIf(“SIP/143-00000024”, “1?trunkcid”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Goto (macro-outbound-callerid,s,14)
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-outbound-callerid:14] ExecIf(“SIP/143-00000024”, “0?Set(CALLERID(all)=)”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-outbound-callerid:15] ExecIf(“SIP/143-00000024”, “0?Set(CALLERID(all)=)”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-outbound-callerid:16] ExecIf(“SIP/143-00000024”, “0?Set(CALLERID(all)=)”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-outbound-callerid:17] ExecIf(“SIP/143-00000024”, “0?Set(CALLERPRES()=prohib_passed_screen)”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-outbound-callerid:18] Set(“SIP/143-00000024”, “CDR(outbound_cnum)=143”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-outbound-callerid:19] Set(“SIP/143-00000024”, “CDR(outbound_cnam)=JOBISH”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-dialout-trunk:12] GosubIf(“SIP/143-00000024”, “0?sub-flp-1,s,1()”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-dialout-trunk:13] Set(“SIP/143-00000024”, “OUTNUM=0558726480”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-dialout-trunk:14] Set(“SIP/143-00000024”, “custom=DAHDI/g0”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-dialout-trunk:15] ExecIf(“SIP/143-00000024”, “0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default))”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-dialout-trunk:16] ExecIf(“SIP/143-00000024”, “0?Set(DIAL_TRUNK_OPTIONS=M(confirm))”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-dialout-trunk:17] Macro(“SIP/143-00000024”, “dialout-trunk-predial-hook,”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit(“SIP/143-00000024”, “”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-dialout-trunk:18] GotoIf(“SIP/143-00000024”, “0?bypass,1”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-dialout-trunk:19] ExecIf(“SIP/143-00000024”, “1?Set(CONNECTEDLINE(num,i)=0558726480)”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-dialout-trunk:20] ExecIf(“SIP/143-00000024”, “1?Set(CONNECTEDLINE(name,i)=CID:143)”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-dialout-trunk:21] GotoIf(“SIP/143-00000024”, “0?customtrunk”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] pbx.c: – Executing [s@macro-dialout-trunk:22] Dial(“SIP/143-00000024”, “DAHDI/g0/0558726480,300,”) in new stack
[2016-07-05 10:47:45] VERBOSE[7049][C-00000020] app_dial.c: – Called DAHDI/g0/0558726480
[2016-07-05 10:47:50] VERBOSE[7049][C-00000020] app_dial.c: – DAHDI/1-1 answered SIP/143-00000024

Thanks advance …

4

What am I looking for. Looks like a FreePBX call that succeeds. (This is the wrong place for FreePBX.)

5

You are using an analog interface, it will always have a small delay until it passes all the digits and connects to the other side.

Try to change from g0 to 1 the zap identifier in your trunk, just in case if the change speed things up.

Before you try changing the zap identifier, in your dahdi trunk fill the outbound dial prefix with the letter w and try again.

6

Thank you, Sorry for delay response , Issue already solved, issue not in our configuration , Its trunk line provider problem …