[Solved] Delay after Asterisk issue the Dial command

1

EDIT : TL;DR; I moved to FreePBX and the issue solved itself. AsteriskNow seems to have a bug within it’s macro. Since I moved to FreePBX without any problems I recommend people to move away from AsteriskNOW until the issue is solved. But this topic has a nice list of checkpoint, feel free to go trough it first.

Hi,

I have a problem with my AsteriskNow installation.

I have a delay on any calls made, right after the “Dial” command. I tested on internal calls, outgoing and incoming.

Here is the log of an incoming call.

The delay occurs after this line : [2016-02-10 10:44:13] VERBOSE[4724][C-00000001] pbx.c: – Executing [s@macro-dial:7] Dial(“SIP/14188638284-00000002”, “SIP/100&SIP/101,20,TtrM(auto-blkvm)”) in new stack

I tried to google a solution, but I’m new to asterisk and I probably haven’t figured out what I should search about… if anyone have suggestions on what to test.

My setup is pretty bassic, only change I made from the basic AsteriskNow installation is trying (and failing) to patch the ODBC problem I have…

Incoming lines are SIP lines. And we’re based in Canada, if the info is of any use…

[2016-02-10 10:44:11] VERBOSE[1925][C-00000001] netsock2.c: == Using SIP RTP TOS bits 184 [2016-02-10 10:44:11] VERBOSE[1925][C-00000001] netsock2.c: == Using SIP RTP CoS mark 5 [2016-02-10 10:44:11] VERBOSE[4724][C-00000001] pbx.c: -- Executing [14188638284@from-trunk:1] NoOp("SIP/14188638284-00000002", "Catch-All DID Match - Found 14188638284 - You probably want a DID for this.") in new stack [2016-02-10 10:44:11] VERBOSE[4724][C-00000001] pbx.c: -- Executing [14188638284@from-trunk:2] Log("SIP/14188638284-00000002", "WARNING,Friendly Scanner from 198.38.7.37") in new stack [2016-02-10 10:44:11] WARNING[4724][C-00000001] Ext. 14188638284: Friendly Scanner from 198.38.7.37 [2016-02-10 10:44:11] VERBOSE[4724][C-00000001] pbx.c: -- Executing [14188638284@from-trunk:3] Set("SIP/14188638284-00000002", "__FROM_DID=14188638284") in new stack [2016-02-10 10:44:11] VERBOSE[4724][C-00000001] pbx.c: -- Executing [14188638284@from-trunk:4] Goto("SIP/14188638284-00000002", "ext-did,s,1") in new stack [2016-02-10 10:44:11] VERBOSE[4724][C-00000001] pbx.c: -- Goto (ext-did,s,1) [2016-02-10 10:44:11] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@ext-did:1] ExecIf("SIP/14188638284-00000002", "0?Set(__FROM_DID=s)") in new stack [2016-02-10 10:44:11] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@ext-did:2] Gosub("SIP/14188638284-00000002", "sub-record-check,s,1(in,s,dontcare)") in new stack [2016-02-10 10:44:11] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@sub-record-check:1] GotoIf("SIP/14188638284-00000002", "0?initialized") in new stack [2016-02-10 10:44:11] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@sub-record-check:2] Set("SIP/14188638284-00000002", "__REC_STATUS=INITIALIZED") in new stack [2016-02-10 10:44:11] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@sub-record-check:3] Set("SIP/14188638284-00000002", "NOW=1455119051") in new stack [2016-02-10 10:44:11] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@sub-record-check:4] Set("SIP/14188638284-00000002", "__DAY=10") in new stack [2016-02-10 10:44:11] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@sub-record-check:5] Set("SIP/14188638284-00000002", "__MONTH=02") in new stack [2016-02-10 10:44:11] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@sub-record-check:6] Set("SIP/14188638284-00000002", "__YEAR=2016") in new stack [2016-02-10 10:44:11] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@sub-record-check:7] Set("SIP/14188638284-00000002", "__TIMESTR=20160210-104411") in new stack [2016-02-10 10:44:11] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@sub-record-check:8] Set("SIP/14188638284-00000002", "__FROMEXTEN=unknown") in new stack [2016-02-10 10:44:11] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@sub-record-check:9] Set("SIP/14188638284-00000002", "__MON_FMT=wav") in new stack [2016-02-10 10:44:11] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@sub-record-check:10] NoOp("SIP/14188638284-00000002", "Recordings initialized") in new stack [2016-02-10 10:44:11] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@sub-record-check:11] ExecIf("SIP/14188638284-00000002", "0?Set(ARG3=dontcare)") in new stack [2016-02-10 10:44:11] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@sub-record-check:12] Set("SIP/14188638284-00000002", "REC_POLICY_MODE_SAVE=") in new stack [2016-02-10 10:44:11] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@sub-record-check:13] ExecIf("SIP/14188638284-00000002", "0?Set(REC_STATUS=NO)") in new stack [2016-02-10 10:44:11] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@sub-record-check:14] GotoIf("SIP/14188638284-00000002", "2?checkaction") in new stack [2016-02-10 10:44:11] VERBOSE[4724][C-00000001] pbx.c: -- Goto (sub-record-check,s,17) [2016-02-10 10:44:11] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@sub-record-check:17] GotoIf("SIP/14188638284-00000002", "1?sub-record-check,in,1") in new stack [2016-02-10 10:44:11] VERBOSE[4724][C-00000001] pbx.c: -- Goto (sub-record-check,in,1) [2016-02-10 10:44:11] VERBOSE[4724][C-00000001] pbx.c: -- Executing [in@sub-record-check:1] NoOp("SIP/14188638284-00000002", "Inbound Recording Check to s") in new stack [2016-02-10 10:44:11] VERBOSE[4724][C-00000001] pbx.c: -- Executing [in@sub-record-check:2] Set("SIP/14188638284-00000002", "FROMEXTEN=unknown") in new stack [2016-02-10 10:44:11] VERBOSE[4724][C-00000001] pbx.c: -- Executing [in@sub-record-check:3] ExecIf("SIP/14188638284-00000002", "11?Set(FROMEXTEN=14188626903)") in new stack [2016-02-10 10:44:11] VERBOSE[4724][C-00000001] pbx.c: -- Executing [in@sub-record-check:4] Gosub("SIP/14188638284-00000002", "recordcheck,1(dontcare,in,s)") in new stack [2016-02-10 10:44:11] VERBOSE[4724][C-00000001] pbx.c: -- Executing [recordcheck@sub-record-check:1] NoOp("SIP/14188638284-00000002", "Starting recording check against dontcare") in new stack [2016-02-10 10:44:11] VERBOSE[4724][C-00000001] pbx.c: -- Executing [recordcheck@sub-record-check:2] Goto("SIP/14188638284-00000002", "dontcare") in new stack [2016-02-10 10:44:11] VERBOSE[4724][C-00000001] pbx.c: -- Goto (sub-record-check,recordcheck,3) [2016-02-10 10:44:11] VERBOSE[4724][C-00000001] pbx.c: -- Executing [recordcheck@sub-record-check:3] Return("SIP/14188638284-00000002", "") in new stack [2016-02-10 10:44:11] VERBOSE[4724][C-00000001] pbx.c: -- Executing [in@sub-record-check:5] Return("SIP/14188638284-00000002", "") in new stack [2016-02-10 10:44:11] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@ext-did:3] Gosub("SIP/14188638284-00000002", "cidlookup,cidlookup_1,1()") in new stack [2016-02-10 10:44:11] VERBOSE[4724][C-00000001] pbx.c: -- Executing [cidlookup_1@cidlookup:1] Set("SIP/14188638284-00000002", "CURLOPT(httptimeout)=7") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [cidlookup_1@cidlookup:2] Set("SIP/14188638284-00000002", "CALLERID(name)=CEGEP RIVIERE D") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [cidlookup_1@cidlookup:3] Set("SIP/14188638284-00000002", "current_hour=2016-02-10 10") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [cidlookup_1@cidlookup:4] Set("SIP/14188638284-00000002", "last_query_hour=2016-02-09 13") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [cidlookup_1@cidlookup:5] Set("SIP/14188638284-00000002", "total_hourly_queries=1") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [cidlookup_1@cidlookup:6] ExecIf("SIP/14188638284-00000002", "1?Set(DB(cidlookup/opencnam_total_hourly_queries)=0)") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [cidlookup_1@cidlookup:7] ExecIf("SIP/14188638284-00000002", "0?Set(DB(cidlookup/opencnam_total_hourly_queries)=0)") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [cidlookup_1@cidlookup:8] Set("SIP/14188638284-00000002", "DB(cidlookup/opencnam_total_hourly_queries)=1") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [cidlookup_1@cidlookup:9] ExecIf("SIP/14188638284-00000002", "0?System(/var/lib/asterisk/bin/opencnam-alert.php)") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [cidlookup_1@cidlookup:10] Set("SIP/14188638284-00000002", "DB(cidlookup/opencnam_last_query_hour)=2016-02-10 10") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [cidlookup_1@cidlookup:11] Return("SIP/14188638284-00000002", "") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@ext-did:4] Gosub("SIP/14188638284-00000002", "app-blacklist-check,s,1()") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@app-blacklist-check:1] GotoIf("SIP/14188638284-00000002", "0?blacklisted") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@app-blacklist-check:2] Set("SIP/14188638284-00000002", "CALLED_BLACKLIST=1") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@app-blacklist-check:3] Return("SIP/14188638284-00000002", "") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@ext-did:5] Set("SIP/14188638284-00000002", "CDR(did)=14188638284") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@ext-did:6] ExecIf("SIP/14188638284-00000002", "0 ?Set(CALLERID(name)=14188626903)") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@ext-did:7] Set("SIP/14188638284-00000002", "CHANNEL(musicclass)=default") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@ext-did:8] Set("SIP/14188638284-00000002", "__MOHCLASS=default") in new stack [2016-02-10 10:44:12] WARNING[4724][C-00000001] func_channel.c: Unknown or unavailable item requested: 'reversecharge' [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@ext-did:9] GotoIf("SIP/14188638284-00000002", "0?macro-hangupcall") in new stack [2016-02-10 10:44:12] WARNING[4724][C-00000001] func_callerid.c: CALLERPRES is deprecated. Use CALLERID(name-pres) or CALLERID(num-pres) instead. [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@ext-did:10] Set("SIP/14188638284-00000002", "__CALLINGPRES_SV=allowed_not_screened") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@ext-did:11] Set("SIP/14188638284-00000002", "CALLERPRES()=allowed_not_screened") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@ext-did:12] Goto("SIP/14188638284-00000002", "timeconditions,2,1") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Goto (timeconditions,2,1) [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [2@timeconditions:1] Set("SIP/14188638284-00000002", "DB(TC/2/INUSESTATE)=INUSE") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [2@timeconditions:2] Set("SIP/14188638284-00000002", "DB(TC/2/NOT_INUSESTATE)=NOT_INUSE") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [2@timeconditions:3] GotoIfTime("SIP/14188638284-00000002", "*,*,24-25,dec?truestate") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [2@timeconditions:4] GotoIfTime("SIP/14188638284-00000002", "*,*,1-2,jan?truestate") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [2@timeconditions:5] GotoIf("SIP/14188638284-00000002", "0?truegoto") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [2@timeconditions:6] ExecIf("SIP/14188638284-00000002", "0?Set(DB(TC/2)=)") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [2@timeconditions:7] Set("SIP/14188638284-00000002", "DEVICE_STATE(Custom:TC2)=INUSE") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [2@timeconditions:8] ExecIf("SIP/14188638284-00000002", "0?Set(DEVICE_STATE(Custom:TCSTICKY)=INUSE)") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [2@timeconditions:9] GotoIf("SIP/14188638284-00000002", "1?timeconditions,1,1") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Goto (timeconditions,1,1) [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [1@timeconditions:1] Set("SIP/14188638284-00000002", "DB(TC/1/INUSESTATE)=INUSE") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [1@timeconditions:2] Set("SIP/14188638284-00000002", "DB(TC/1/NOT_INUSESTATE)=NOT_INUSE") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [1@timeconditions:3] GotoIfTime("SIP/14188638284-00000002", "09:00-17:00,mon-thu,*,*?truestate") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Goto (timeconditions,1,13) [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [1@timeconditions:13] GotoIf("SIP/14188638284-00000002", "0?falsegoto") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [1@timeconditions:14] ExecIf("SIP/14188638284-00000002", "0?Set(DB(TC/1)=)") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [1@timeconditions:15] Set("SIP/14188638284-00000002", "DEVICE_STATE(Custom:TC1)=NOT_INUSE") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [1@timeconditions:16] ExecIf("SIP/14188638284-00000002", "0?Set(DEVICE_STATE(Custom:TCSTICKY)=INUSE)") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [1@timeconditions:17] GotoIf("SIP/14188638284-00000002", "1?ext-group,600,1") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Goto (ext-group,600,1) [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [600@ext-group:1] Macro("SIP/14188638284-00000002", "user-callerid,") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@macro-user-callerid:1] Set("SIP/14188638284-00000002", "TOUCH_MONITOR=1455119051.2") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@macro-user-callerid:2] Set("SIP/14188638284-00000002", "AMPUSER=14188626903") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@macro-user-callerid:3] GotoIf("SIP/14188638284-00000002", "0?report") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@macro-user-callerid:4] ExecIf("SIP/14188638284-00000002", "1?Set(REALCALLERIDNUM=14188626903)") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@macro-user-callerid:5] Set("SIP/14188638284-00000002", "AMPUSER=") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@macro-user-callerid:6] GotoIf("SIP/14188638284-00000002", "0?limit") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@macro-user-callerid:7] Set("SIP/14188638284-00000002", "AMPUSERCIDNAME=") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@macro-user-callerid:8] GotoIf("SIP/14188638284-00000002", "1?report") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Goto (macro-user-callerid,s,16) [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@macro-user-callerid:16] GotoIf("SIP/14188638284-00000002", "0?continue") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@macro-user-callerid:17] ExecIf("SIP/14188638284-00000002", "1?Set(__CALLEE_ACCOUNCODE=)") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@macro-user-callerid:18] Set("SIP/14188638284-00000002", "__TTL=64") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@macro-user-callerid:19] GotoIf("SIP/14188638284-00000002", "1?continue") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Goto (macro-user-callerid,s,30) [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@macro-user-callerid:30] Set("SIP/14188638284-00000002", "CALLERID(number)=14188626903") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@macro-user-callerid:31] Set("SIP/14188638284-00000002", "CALLERID(name)=CEGEP RIVIERE D") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@macro-user-callerid:32] Set("SIP/14188638284-00000002", "CDR(cnum)=14188626903") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@macro-user-callerid:33] Set("SIP/14188638284-00000002", "CDR(cnam)=CEGEP RIVIERE D") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@macro-user-callerid:34] Set("SIP/14188638284-00000002", "CHANNEL(language)=fr") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [600@ext-group:2] Macro("SIP/14188638284-00000002", "blkvm-setifempty,") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@macro-blkvm-setifempty:1] GotoIf("SIP/14188638284-00000002", "1?init") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Goto (macro-blkvm-setifempty,s,4) [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@macro-blkvm-setifempty:4] Set("SIP/14188638284-00000002", "__BLKVM_CHANNEL=SIP/14188638284-00000002") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@macro-blkvm-setifempty:5] Set("SIP/14188638284-00000002", "SHARED(BLKVM,SIP/14188638284-00000002)=TRUE") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@macro-blkvm-setifempty:6] Set("SIP/14188638284-00000002", "GOSUB_RETVAL=TRUE") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@macro-blkvm-setifempty:7] MacroExit("SIP/14188638284-00000002", "") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [600@ext-group:3] GotoIf("SIP/14188638284-00000002", "1?skipov") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Goto (ext-group,600,6) [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [600@ext-group:6] Set("SIP/14188638284-00000002", "RRNODEST=") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [600@ext-group:7] Set("SIP/14188638284-00000002", "__NODEST=600") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [600@ext-group:8] GosubIf("SIP/14188638284-00000002", "0?sub-rgsetcid,s,1()") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [600@ext-group:9] Gosub("SIP/14188638284-00000002", "sub-record-check,s,1(rg,600,dontcare)") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@sub-record-check:1] GotoIf("SIP/14188638284-00000002", "11?initialized") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Goto (sub-record-check,s,10) [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@sub-record-check:10] NoOp("SIP/14188638284-00000002", "Recordings initialized") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@sub-record-check:11] ExecIf("SIP/14188638284-00000002", "0?Set(ARG3=dontcare)") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@sub-record-check:12] Set("SIP/14188638284-00000002", "REC_POLICY_MODE_SAVE=") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@sub-record-check:13] ExecIf("SIP/14188638284-00000002", "0?Set(REC_STATUS=NO)") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@sub-record-check:14] GotoIf("SIP/14188638284-00000002", "2?checkaction") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Goto (sub-record-check,s,17) [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@sub-record-check:17] GotoIf("SIP/14188638284-00000002", "0?sub-record-check,rg,1") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@sub-record-check:18] NoOp("SIP/14188638284-00000002", "Generic rg Recording Check - 14188626903 600") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@sub-record-check:19] Gosub("SIP/14188638284-00000002", "recordcheck,1(dontcare,rg,600)") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [recordcheck@sub-record-check:1] NoOp("SIP/14188638284-00000002", "Starting recording check against dontcare") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [recordcheck@sub-record-check:2] Goto("SIP/14188638284-00000002", "dontcare") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Goto (sub-record-check,recordcheck,3) [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [recordcheck@sub-record-check:3] Return("SIP/14188638284-00000002", "") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@sub-record-check:20] Return("SIP/14188638284-00000002", "") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [600@ext-group:10] Set("SIP/14188638284-00000002", "RingGroupMethod=ringall") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [600@ext-group:11] Macro("SIP/14188638284-00000002", "dial,20,Ttr,100-101") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@macro-dial:1] GotoIf("SIP/14188638284-00000002", "0?dial") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@macro-dial:2] Set("SIP/14188638284-00000002", "CHANNEL(musicclass)=default") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@macro-dial:3] AGI("SIP/14188638284-00000002", "dialparties.agi") in new stack [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] res_agi.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] res_agi.c: dialparties.agi: Starting New Dialparties.agi [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] res_agi.c: dialparties.agi: Caller ID name is 'CEGEP RIVIERE D' number is '14188626903' [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] res_agi.c: dialparties.agi: Methodology of ring is 'ringall' [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] res_agi.c: -- dialparties.agi: Added extension 100 to extension map [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] res_agi.c: -- dialparties.agi: Added extension 101 to extension map [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] res_agi.c: -- dialparties.agi: Extension 100 cf is disabled [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] res_agi.c: -- dialparties.agi: Extension 101 cf is disabled [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] res_agi.c: -- dialparties.agi: Extension 100 do not disturb is disabled [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] res_agi.c: -- dialparties.agi: Extension 101 do not disturb is disabled [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] res_agi.c: -- dialparties.agi: dbset CALLTRACE/100 to 14188626903 [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] res_agi.c: -- dialparties.agi: dbset CALLTRACE/101 to 14188626903 [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] res_agi.c: -- dialparties.agi: Filtered ARG3: 100-101 [2016-02-10 10:44:12] VERBOSE[4724][C-00000001] res_agi.c: -- <SIP/14188638284-00000002>AGI Script dialparties.agi completed, returning 0 [2016-02-10 10:44:13] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@macro-dial:7] Dial("SIP/14188638284-00000002", "SIP/100&SIP/101,20,TtrM(auto-blkvm)") in new stack [2016-02-10 10:44:22] VERBOSE[4724][C-00000001] netsock2.c: == Using SIP RTP TOS bits 184 [2016-02-10 10:44:22] VERBOSE[4724][C-00000001] netsock2.c: == Using SIP RTP CoS mark 5 [2016-02-10 10:44:31] VERBOSE[4724][C-00000001] netsock2.c: == Using SIP RTP TOS bits 184 [2016-02-10 10:44:31] VERBOSE[4724][C-00000001] netsock2.c: == Using SIP RTP CoS mark 5 [2016-02-10 10:44:31] VERBOSE[4724][C-00000001] app_dial.c: -- Called SIP/100 [2016-02-10 10:44:31] VERBOSE[4724][C-00000001] app_dial.c: -- Called SIP/101 [2016-02-10 10:44:31] VERBOSE[4724][C-00000001] app_dial.c: -- SIP/101-00000004 connected line has changed. Saving it until answer for SIP/14188638284-00000002 [2016-02-10 10:44:31] VERBOSE[4724][C-00000001] app_dial.c: -- SIP/100-00000003 connected line has changed. Saving it until answer for SIP/14188638284-00000002 [2016-02-10 10:44:31] VERBOSE[4724][C-00000001] app_dial.c: -- SIP/101-00000004 is ringing [2016-02-10 10:44:31] VERBOSE[4724][C-00000001] app_dial.c: -- SIP/100-00000003 is ringing [2016-02-10 10:44:34] VERBOSE[4724][C-00000001] app_dial.c: -- SIP/100-00000003 connected line has changed. Saving it until answer for SIP/14188638284-00000002 [2016-02-10 10:44:34] VERBOSE[4724][C-00000001] app_dial.c: -- SIP/100-00000003 answered SIP/14188638284-00000002 [2016-02-10 10:44:34] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@macro-auto-blkvm:1] Set("SIP/100-00000003", "__MACRO_RESULT=") in new stack [2016-02-10 10:44:34] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@macro-auto-blkvm:2] Set("SIP/100-00000003", "CFIGNORE=") in new stack [2016-02-10 10:44:34] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@macro-auto-blkvm:3] Set("SIP/100-00000003", "MASTER_CHANNEL(CFIGNORE)=") in new stack [2016-02-10 10:44:34] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@macro-auto-blkvm:4] Set("SIP/100-00000003", "FORWARD_CONTEXT=from-internal") in new stack [2016-02-10 10:44:34] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@macro-auto-blkvm:5] Set("SIP/100-00000003", "MASTER_CHANNEL(FORWARD_CONTEXT)=from-internal") in new stack [2016-02-10 10:44:34] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@macro-auto-blkvm:6] Macro("SIP/100-00000003", "blkvm-clr,") in new stack [2016-02-10 10:44:34] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@macro-blkvm-clr:1] Set("SIP/100-00000003", "SHARED(BLKVM,SIP/14188638284-00000002)=") in new stack [2016-02-10 10:44:34] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@macro-blkvm-clr:2] Set("SIP/100-00000003", "GOSUB_RETVAL=") in new stack [2016-02-10 10:44:34] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@macro-blkvm-clr:3] MacroExit("SIP/100-00000003", "") in new stack [2016-02-10 10:44:34] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@macro-auto-blkvm:7] ExecIf("SIP/100-00000003", "0?Set(MASTER_CHANNEL(CONNECTEDLINE(num))=100)") in new stack [2016-02-10 10:44:34] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@macro-auto-blkvm:8] ExecIf("SIP/100-00000003", "0?Set(MASTER_CHANNEL(CONNECTEDLINE(name))=Sebastien Lemieux)") in new stack [2016-02-10 10:44:34] VERBOSE[4724][C-00000001] pbx.c: -- Executing [h@macro-dial:1] Macro("SIP/14188638284-00000002", "hangupcall") in new stack [2016-02-10 10:44:34] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@macro-hangupcall:1] ExecIf("SIP/14188638284-00000002", "0?Set(CDR(recordingfile)=.wav)") in new stack [2016-02-10 10:44:34] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@macro-hangupcall:2] GotoIf("SIP/14188638284-00000002", "1?theend") in new stack [2016-02-10 10:44:34] VERBOSE[4724][C-00000001] pbx.c: -- Goto (macro-hangupcall,s,4) [2016-02-10 10:44:34] VERBOSE[4724][C-00000001] pbx.c: -- Executing [s@macro-hangupcall:4] Hangup("SIP/14188638284-00000002", "") in new stack [2016-02-10 10:44:34] VERBOSE[4724][C-00000001] app_macro.c: == Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SIP/14188638284-00000002' in macro 'hangupcall' [2016-02-10 10:44:34] VERBOSE[4724][C-00000001] pbx.c: == Spawn extension (macro-dial, h, 1) exited non-zero on 'SIP/14188638284-00000002' [2016-02-10 10:44:34] ERROR[4724][C-00000001] cdr_odbc.c: Unable to retrieve database handle. CDR failed. [2016-02-10 10:44:34] VERBOSE[4724][C-00000001] app_macro.c: == Spawn extension (macro-dial, s, 7) exited non-zero on 'SIP/14188638284-00000002' in macro 'dial' [2016-02-10 10:44:34] VERBOSE[4724][C-00000001] pbx.c: == Spawn extension (ext-group, 600, 11) exited non-zero on 'SIP/14188638284-00000002'

2

Delays at that stage are typically due to DNS misconfigurations.

3

Thanks for the hint.

I looked into DNS, and I failed to find any information or I couldn’t solve the problem.

I had the localhost in my resolv.conf file and my firewall (Untangle). I removed the firewall from my DNS entry, leaving only the localhost as a DNS server, and I still have that delay, for any type of call… shouldn’t it solve at least the internal call ? (I may be wrong on this assumption). I know my change works because now the Asterisk can’t do opencnam query.

Is there a way to deactivate any reverse DNS made from Asterisk ? It would help to narrow down the exact problem I have…

4

Could you explain network setup please. Where is asterisk/phones and networking interfaces

5

Yes. network isn’t something big.

Internet | | Cable Modem | | Untangle (physical server) | | Dlink 5-port switch ---- Power Injector --- Telephone --- Computer (this line exists twice, once for each employee) | | VMWare ESXI ---- Asterisk server (virtualised)

I already did a bunch of optimisation on the Untangle and the ESXi platform. I made sure I had no disk related issue and/or solved any latency issue I could find for now. It did made the Asterisk a little faster to pick calls. And Untangle is indeed quite a mess for SIP lines, but it shouldn’t impact inside calls.

EDIT : I continue working on this, I got problems lately with DNS resolution (Asterisk telling me he can’t resolve url to my external sip lines). I added Google’s DNS, it solved the new problem but I still have this delay on ay form of call.

6

I’m bumping this thread since it’s been a week since the last reply…

I continued to work on the problem. I can see changes in the problem when I play around with DNS settings, but I can’t get under the 10sec delay I have now…

Was there a way to completely remove any reverse DNS call from Asterisk ? It would help figuring out if the DNS resolution is the only problem or if I have to dig something else around.

I also bought the O’reilly asterisk book, but it will take some time to go trough it. If someone has any sort of solution in the meantime it would be really appreciated.

7

On the Chan SIP page in SIP settings and on the General SIP Settings I had the wrong IP address configured (power outage may have recycled my public IP)… I configured the Chan SIP with a dynamic host that is working properly, but the General SIP Setting were using an old IP.

Could this cause the problem I have now ? I cannot test it properly, I will have to wait maybe a day or two. I found out that after calling the same number a couple of time they delay I had with my system is gone.

8

The problem came back this morning, so the IP settings on the chan sip wasn’t at fault.

I installed a new AsteriskNow system, physical this time. I did the minimum configuration to get my SIP trunk up, outbound and insbound route, and one extension. And I have the exact same delay problem. This test is kinda ruling out the virtual environment as a problem.

Everything really points out to the DNS problem. I changed all dynamic dns entry reference (with no-ip) to my actual public IP, with no luck…

I know this is a community forum and people give helps on their own free time, but I’d really like the community to get involved… I’m still looking for a solution, 13 days without any reply from someone feels kinda sad though :-S I’d love to find a solution and write a tutorial about it as a reference for the next one who’ll get that problem. But I need a solution for this XD

9

I’m not sure if anyone can really add anything else besides it pointing towards DNS problems. Isolate that and examine it. Look at DNS traffic and see if requests are taking a long time. See if some are never answered. If DNS is not fast and some requests take awhile then chan_sip will block at times. It’s not written to use asynchronous DNS.

10

I continued working around the DNS problem. We had domain names on our SIP trunk, I removed them. Then I looked at a tcpdump…

I have one question : SHould I keep 127.0.0.1 as a first dns server in my resolv.conf file ? I have the basic AsteriskNow setup, I don’t have a local DNS server… it doesn’t cause any problem when I do DNS query with nslookup, but could if affect Asterisk ?

EDIT : I removed it to test, and it changed nothing. My tcpdump command doesn’t show any DNS query going out
command used :
tcpdump -vvv -s 0 -l -n port 53

As much as I want to believe DNS is involved, I’m starting to doubt that. The only moment where any sort of dns problem would be involved in this server is on outgoing, incoming and internal calls, and with the latest test I did I really don’t see where the problem could be…

11

Adding informations :slightly_smiling:

With an IVR, we can skip a part of the delay. Incoming calls are picked up instantly. Kinda confirm that the problem occurs on the Dial() command…

I tried to read about DNS management in Asterisk, but for now I haven’t really found anything outside “set 127.0.0.1 as first dns” and “DNS with asterisk is problematic”.

Is there any doc about DNS management in Asterisk somewhere ?

12

Bump.

I activated dnsmgr in Asterisk, in hope to find a solution or at least a clear explanation to the problem.

I did a couple of calls, still have the delay on the Dial command. And dnsmgr status shows 0 entries…

My guess would be that DNS is out of the question here…

Could Caller id cause this ?

13

The dnsmgr functionality is not used by chan_sip for calling like that, and will only help in limited scope for other cases. It is unlikely that caller id would cause this.

14

I activated OpenCNAM on the trunk. It did changed my caller id to something he got from the OpenCNAM query, but I still have the delay.

You’re right that caller id doesn’t cause this… Am I correct with the test I did with dnsmgr ? I really need to get trough this quickly, but I’m starting to lose hope into Asterisk as a reliable solution for my service… Do all Asterisk servers have that delay ?

15

Since chan_sip doesn’t use dnsmgr in that way it won’t help, so trying it would have made no difference. And no, other Asterisk servers do not have that delay. Every case I’ve run into has been the result of DNS. Once that was fixed then it was fine.

16

And how did you solved it ? We did heavy testing on all our servers about DNS queries, we have between 10ms and 20ms of delay on dns query on all servers, even from the Asterisk server CLI…

I have absolutely no clue where to look from here.any nslookup query returned result instantly, With any domains we tested, either the one from my SIP line providers, or any domain name we could test on (our domains, our clients domains, google…).

I am trying to figure this out. You make it sounds easy, but after a lot of hours I still haven’t figured it out… What could I do wrong here ?

17

Usually the DNS server specified is wrong or down, which results in it taking awhile. A caching DNS server can also help. Another problem that can be run into is /etc/hosts not containing the local hostname, which is needed.

18

Specified DNS are 127.0.0.1, 10.0.0.1 (untangle), 8.8.8.8 and 8.8.4.4

I’m not running a local BIND server on the Asterisk, should I remove 127.0.0.1 from there ?

I’ll play with the local hostname to see if it’s properly configured

EDIT : Hostname wasn’t set properly. I changed it, but I still have the delay. I’m using AsteriskNow, so I changed it by the web interface. A ping from any other machine on the network resolve the asterisknow hostname to 10.0.0.250 (I added a static DNS entry in my firewall), the server’s IP. A ping to asterisknow on the Asterisk server resolve to 127.0.0.1

EDIT 2 : A trend started to show while working on this. In the morning (UTC-5) we have the delay problem. Somewhere in the afternoon it stops…

19

If you are not running a local DNS server then you do not want to be querying one.

I’d just query the google DNS servers and skip the other two.

My DNS works properly and I have never had a delay when dialing.

20

Hi,

I had the same problem as you when using a M(macro) on the dial, while the macro is not completed its dial is stuck.
Remove the macro for testing, resolve check what your doing macro take to complete and the last line includes MacroExit.

Good luck.