Since last update IVR is not working properly

General Help
1

I’ve just installed the fop2admin module with the FOP2 service and it works.

I’ve used the time also to updated all official modules from FreePBX.

I’ve also changed the wait timeout for all queues to Unlimited (it used to be 15 minutes).

Now, after all that my IVR doesn’t work properly with Queues; and as you can imagine I don’t know which one of those broke it.

Here’s the step-by-step for the call:

  1. Somebody calls any of my Inbound Routes.
  2. Time Condition first check if the time is right
  3. Since it’s opening hours, it sends you to the IVR
  4. The IVR sends you to a Queue (depending on the key you pressed)
  5. Then the phone on all the members of the Queue rings
  6. Somebody picks it up, and…

All that seems to work just fine, but when at the last step you pick up the phone, the call is automatically hanged up, and the caller is returned to the IVR for an eternal loop (you press a key, ringing, IVR, press a key, ringing…)

I’ve temporarily fixed it by sendind the users directly to the main (support) queue, but it’s annoying since they have to forward calls manually when they were meant to reach another queue (ie. sales, payment, other extensions, etc).

What could be wrong with my setup?

I’ll reply this topic attaching a few asterisk call logs in case that helps. I have the last FreePBX version (as I’ve said I’ve updated everything), and it’s running on CentOS 6 x64.

2

[2013-05-15 19:06:43] VERBOSE[28009][C-00000007] pbx.c: – Executing [01153521491@from-trunk-sip-GWSIP1:1] Set(“SIP/190.210.6.162-0000000e”, “GROUP()=OUT_23”) in new stack
[2013-05-15 19:06:43] VERBOSE[28009][C-00000007] pbx.c: – Executing [01153521491@from-trunk-sip-GWSIP1:2] Goto(“SIP/190.210.6.162-0000000e”, “from-trunk,01153521491,1”) in new stack
[2013-05-15 19:06:43] VERBOSE[28009][C-00000007] pbx.c: – Goto (from-trunk,01153521491,1)
[2013-05-15 19:06:43] VERBOSE[28009][C-00000007] pbx.c: – Executing [01153521491@from-trunk:1] Set(“SIP/190.210.6.162-0000000e”, “__FROM_DID=01153521491”) in new stack
[2013-05-15 19:06:43] VERBOSE[28009][C-00000007] pbx.c: – Executing [01153521491@from-trunk:2] Gosub(“SIP/190.210.6.162-0000000e”, “app-blacklist-check,s,1()”) in new stack
[2013-05-15 19:06:43] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@app-blacklist-check:1] GotoIf(“SIP/190.210.6.162-0000000e”, “0?blacklisted”) in new stack
[2013-05-15 19:06:43] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@app-blacklist-check:2] Set(“SIP/190.210.6.162-0000000e”, “CALLED_BLACKLIST=1”) in new stack
[2013-05-15 19:06:43] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@app-blacklist-check:3] Return(“SIP/190.210.6.162-0000000e”, “”) in new stack
[2013-05-15 19:06:43] VERBOSE[28009][C-00000007] pbx.c: – Executing [01153521491@from-trunk:3] Set(“SIP/190.210.6.162-0000000e”, “CDR(did)=01153521491”) in new stack
[2013-05-15 19:06:43] VERBOSE[28009][C-00000007] pbx.c: – Executing [01153521491@from-trunk:4] ExecIf(“SIP/190.210.6.162-0000000e”, “1 ?Set(CALLERID(name)=1156921341)”) in new stack
[2013-05-15 19:06:43] VERBOSE[28009][C-00000007] pbx.c: – Executing [01153521491@from-trunk:5] Set(“SIP/190.210.6.162-0000000e”, “CHANNEL(musicclass)=WIROOS”) in new stack
[2013-05-15 19:06:43] VERBOSE[28009][C-00000007] pbx.c: – Executing [01153521491@from-trunk:6] Set(“SIP/190.210.6.162-0000000e”, “__MOHCLASS=WIROOS”) in new stack
[2013-05-15 19:06:43] VERBOSE[28009][C-00000007] pbx.c: – Executing [01153521491@from-trunk:7] Set(“SIP/190.210.6.162-0000000e”, “__CALLINGPRES_SV=allowed_not_screened”) in new stack
[2013-05-15 19:06:43] VERBOSE[28009][C-00000007] pbx.c: – Executing [01153521491@from-trunk:8] Set(“SIP/190.210.6.162-0000000e”, “CALLERPRES()=allowed_not_screened”) in new stack
[2013-05-15 19:06:43] VERBOSE[28009][C-00000007] pbx.c: – Executing [01153521491@from-trunk:9] Goto(“SIP/190.210.6.162-0000000e”, “timeconditions,3,1”) in new stack
[2013-05-15 19:06:43] VERBOSE[28009][C-00000007] pbx.c: – Goto (timeconditions,3,1)
[2013-05-15 19:06:43] VERBOSE[28009][C-00000007] pbx.c: – Executing [3@timeconditions:1] GotoIfTime(“SIP/190.210.6.162-0000000e”, “00:00-23:59,,31-1,dec-jan?truestate") in new stack
[2013-05-15 19:06:43] VERBOSE[28009][C-00000007] pbx.c: – Executing [3@timeconditions:2] GotoIf(“SIP/190.210.6.162-0000000e”, “0?truegoto”) in new stack
[2013-05-15 19:06:43] VERBOSE[28009][C-00000007] pbx.c: – Executing [3@timeconditions:3] ExecIf(“SIP/190.210.6.162-0000000e”, “0?Set(DB(TC/3)=)”) in new stack
[2013-05-15 19:06:43] VERBOSE[28009][C-00000007] pbx.c: – Executing [3@timeconditions:4] GotoIf(“SIP/190.210.6.162-0000000e”, “1?timeconditions,1,1”) in new stack
[2013-05-15 19:06:43] VERBOSE[28009][C-00000007] pbx.c: – Goto (timeconditions,1,1)
[2013-05-15 19:06:43] VERBOSE[28009][C-00000007] pbx.c: – Executing [1@timeconditions:1] GotoIfTime(“SIP/190.210.6.162-0000000e”, "22:00-23:59,mon-fri,,?truestate") in new stack
[2013-05-15 19:06:43] VERBOSE[28009][C-00000007] pbx.c: – Executing [1@timeconditions:2] GotoIfTime(“SIP/190.210.6.162-0000000e”, "00:00-08:00,mon-fri,,?truestate") in new stack
[2013-05-15 19:06:43] VERBOSE[28009][C-00000007] pbx.c: – Executing [1@timeconditions:3] GotoIfTime(“SIP/190.210.6.162-0000000e”, "00:00-23:59,sat-sun,,*?truestate”) in new stack
[2013-05-15 19:06:43] VERBOSE[28009][C-00000007] pbx.c: – Executing [1@timeconditions:4] GotoIf(“SIP/190.210.6.162-0000000e”, “0?truegoto”) in new stack
[2013-05-15 19:06:43] VERBOSE[28009][C-00000007] pbx.c: – Executing [1@timeconditions:5] ExecIf(“SIP/190.210.6.162-0000000e”, “0?Set(DB(TC/1)=)”) in new stack
[2013-05-15 19:06:43] VERBOSE[28009][C-00000007] pbx.c: – Executing [1@timeconditions:6] GotoIf(“SIP/190.210.6.162-0000000e”, “1?ivr-2,s,1”) in new stack
[2013-05-15 19:06:43] VERBOSE[28009][C-00000007] pbx.c: – Goto (ivr-2,s,1)
[2013-05-15 19:06:43] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@ivr-2:1] Set(“SIP/190.210.6.162-0000000e”, “_IVR_CONTEXT_ivr-2=”) in new stack
[2013-05-15 19:06:43] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@ivr-2:2] Set(“SIP/190.210.6.162-0000000e”, “_IVR_CONTEXT=ivr-2”) in new stack
[2013-05-15 19:06:43] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@ivr-2:3] Set(“SIP/190.210.6.162-0000000e”, “__IVR_RETVM=”) in new stack
[2013-05-15 19:06:43] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@ivr-2:4] GotoIf(“SIP/190.210.6.162-0000000e”, “0?skip”) in new stack
[2013-05-15 19:06:43] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@ivr-2:5] Answer(“SIP/190.210.6.162-0000000e”, “”) in new stack
[2013-05-15 19:06:43] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@ivr-2:6] Wait(“SIP/190.210.6.162-0000000e”, “1”) in new stack
[2013-05-15 19:06:44] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@ivr-2:7] Set(“SIP/190.210.6.162-0000000e”, “IVR_MSG=custom/WIROOS-IVR”) in new stack
[2013-05-15 19:06:44] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@ivr-2:8] Set(“SIP/190.210.6.162-0000000e”, “TIMEOUT(digit)=3”) in new stack
[2013-05-15 19:06:44] VERBOSE[28009][C-00000007] func_timeout.c: – Digit timeout set to 3.000
[2013-05-15 19:06:44] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@ivr-2:9] ExecIf(“SIP/190.210.6.162-0000000e”, “1?Background(custom/WIROOS-IVR)”) in new stack
[2013-05-15 19:06:44] VERBOSE[28009][C-00000007] file.c: – <SIP/190.210.6.162-0000000e> Playing ‘custom/WIROOS-IVR.gsm’ (language ‘en’)
[2013-05-15 19:06:57] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@ivr-2:10] WaitExten(“SIP/190.210.6.162-0000000e”, “10,”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Timeout on SIP/190.210.6.162-0000000e, going to ‘t’
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [t@ivr-2:1] Goto(“SIP/190.210.6.162-0000000e”, “from-did-direct,107,1”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Goto (from-did-direct,107,1)
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [107@from-did-direct:1] Set(“SIP/190.210.6.162-0000000e”, “__RINGTIMER=15”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [107@from-did-direct:2] Macro(“SIP/190.210.6.162-0000000e”, “exten-vm,novm,107,0,0,0”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-exten-vm:1] Macro(“SIP/190.210.6.162-0000000e”, “user-callerid,”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-user-callerid:1] Set(“SIP/190.210.6.162-0000000e”, “TOUCH_MONITOR=1368655603.38”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-user-callerid:2] Set(“SIP/190.210.6.162-0000000e”, “AMPUSER=1156921341”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-user-callerid:3] GotoIf(“SIP/190.210.6.162-0000000e”, “0?report”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-user-callerid:4] ExecIf(“SIP/190.210.6.162-0000000e”, “1?Set(REALCALLERIDNUM=1156921341)”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-user-callerid:5] Set(“SIP/190.210.6.162-0000000e”, “AMPUSER=”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-user-callerid:6] Set(“SIP/190.210.6.162-0000000e”, “AMPUSERCIDNAME=”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-user-callerid:7] GotoIf(“SIP/190.210.6.162-0000000e”, “1?report”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Goto (macro-user-callerid,s,15)
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-user-callerid:15] GotoIf(“SIP/190.210.6.162-0000000e”, “0?continue”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-user-callerid:16] Set(“SIP/190.210.6.162-0000000e”, “__TTL=64”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-user-callerid:17] GotoIf(“SIP/190.210.6.162-0000000e”, “1?continue”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Goto (macro-user-callerid,s,28)
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-user-callerid:28] Set(“SIP/190.210.6.162-0000000e”, “CALLERID(number)=1156921341”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-user-callerid:29] Set(“SIP/190.210.6.162-0000000e”, “CALLERID(name)=1156921341”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-user-callerid:30] Set(“SIP/190.210.6.162-0000000e”, “CDR(cnum)=1156921341”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-user-callerid:31] Set(“SIP/190.210.6.162-0000000e”, “CDR(cnam)=1156921341”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-user-callerid:32] Set(“SIP/190.210.6.162-0000000e”, “CHANNEL(language)=en”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-exten-vm:2] Set(“SIP/190.210.6.162-0000000e”, “RingGroupMethod=none”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-exten-vm:3] Set(“SIP/190.210.6.162-0000000e”, “__EXTTOCALL=107”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-exten-vm:4] Set(“SIP/190.210.6.162-0000000e”, “__PICKUPMARK=107”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-exten-vm:5] Set(“SIP/190.210.6.162-0000000e”, “RT=15”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-exten-vm:6] Gosub(“SIP/190.210.6.162-0000000e”, “sub-record-check,s,1(exten,107,)”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@sub-record-check:1] Set(“SIP/190.210.6.162-0000000e”, “REC_POLICY_MODE_SAVE=”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@sub-record-check:2] GotoIf(“SIP/190.210.6.162-0000000e”, “1?check”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Goto (sub-record-check,s,7)
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@sub-record-check:7] Set(“SIP/190.210.6.162-0000000e”, “__MON_FMT=wav”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@sub-record-check:8] GotoIf(“SIP/190.210.6.162-0000000e”, “1?next”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Goto (sub-record-check,s,11)
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@sub-record-check:11] ExecIf(“SIP/190.210.6.162-0000000e”, “0?Return()”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@sub-record-check:12] ExecIf(“SIP/190.210.6.162-0000000e”, “0?Set(__REC_POLICY_MODE=)”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@sub-record-check:13] GotoIf(“SIP/190.210.6.162-0000000e”, “0?exten,1”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@sub-record-check:14] Set(“SIP/190.210.6.162-0000000e”, “__REC_STATUS=INITIALIZED”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@sub-record-check:15] Set(“SIP/190.210.6.162-0000000e”, “NOW=1368655627”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@sub-record-check:16] Set(“SIP/190.210.6.162-0000000e”, “__DAY=15”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@sub-record-check:17] Set(“SIP/190.210.6.162-0000000e”, “__MONTH=05”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@sub-record-check:18] Set(“SIP/190.210.6.162-0000000e”, “__YEAR=2013”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@sub-record-check:19] Set(“SIP/190.210.6.162-0000000e”, “__TIMESTR=20130515-190707”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@sub-record-check:20] Set(“SIP/190.210.6.162-0000000e”, “__FROMEXTEN=1156921341”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@sub-record-check:21] Set(“SIP/190.210.6.162-0000000e”, “__CALLFILENAME=exten-107-1156921341-20130515-190707-1368655603.38”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@sub-record-check:22] Goto(“SIP/190.210.6.162-0000000e”, “exten,1”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Goto (sub-record-check,exten,1)
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [exten@sub-record-check:1] GotoIf(“SIP/190.210.6.162-0000000e”, “0?callee”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [exten@sub-record-check:2] Set(“SIP/190.210.6.162-0000000e”, “__REC_POLICY_MODE=dontcare”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [exten@sub-record-check:3] GotoIf(“SIP/190.210.6.162-0000000e”, “1?caller”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Goto (sub-record-check,exten,10)
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [exten@sub-record-check:10] Set(“SIP/190.210.6.162-0000000e”, “__REC_POLICY_MODE=”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [exten@sub-record-check:11] GosubIf(“SIP/190.210.6.162-0000000e”, “0?record,1(exten,107,1156921341)”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [exten@sub-record-check:12] Return(“SIP/190.210.6.162-0000000e”, “”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-exten-vm:7] GotoIf(“SIP/190.210.6.162-0000000e”, “1?macrodial”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Goto (macro-exten-vm,s,13)
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-exten-vm:13] GosubIf(“SIP/190.210.6.162-0000000e”, “0?clrheader,1()”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-exten-vm:14] Macro(“SIP/190.210.6.162-0000000e”, “dial-one,15,tr,107”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-dial-one:1] Set(“SIP/190.210.6.162-0000000e”, “DEXTEN=107”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-dial-one:2] Set(“SIP/190.210.6.162-0000000e”, “DIALSTATUS_CW=”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-dial-one:3] GosubIf(“SIP/190.210.6.162-0000000e”, “0?screen,1()”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-dial-one:4] GosubIf(“SIP/190.210.6.162-0000000e”, “0?cf,1()”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-dial-one:5] GotoIf(“SIP/190.210.6.162-0000000e”, “1?skip1”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Goto (macro-dial-one,s,8)
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-dial-one:8] GotoIf(“SIP/190.210.6.162-0000000e”, “0?nodial”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-dial-one:9] GotoIf(“SIP/190.210.6.162-0000000e”, “0?continue”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-dial-one:10] Set(“SIP/190.210.6.162-0000000e”, “EXTHASCW=ENABLED”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-dial-one:11] GotoIf(“SIP/190.210.6.162-0000000e”, “0?next1:cwinusebusy”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Goto (macro-dial-one,s,23)
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-dial-one:23] GotoIf(“SIP/190.210.6.162-0000000e”, “1?next3:continue”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Goto (macro-dial-one,s,24)
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-dial-one:24] ExecIf(“SIP/190.210.6.162-0000000e”, “0?Set(DIALSTATUS_CW=BUSY)”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-dial-one:25] GotoIf(“SIP/190.210.6.162-0000000e”, “0?nodial”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-dial-one:26] GosubIf(“SIP/190.210.6.162-0000000e”, “1?dstring,1():dlocal,1()”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [dstring@macro-dial-one:1] Set(“SIP/190.210.6.162-0000000e”, “DSTRING=”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [dstring@macro-dial-one:2] Set(“SIP/190.210.6.162-0000000e”, “DEVICES=107”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [dstring@macro-dial-one:3] ExecIf(“SIP/190.210.6.162-0000000e”, “0?Return()”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [dstring@macro-dial-one:4] ExecIf(“SIP/190.210.6.162-0000000e”, “0?Set(DEVICES=07)”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [dstring@macro-dial-one:5] Set(“SIP/190.210.6.162-0000000e”, “LOOPCNT=1”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [dstring@macro-dial-one:6] Set(“SIP/190.210.6.162-0000000e”, “ITER=1”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [dstring@macro-dial-one:7] Set(“SIP/190.210.6.162-0000000e”, “THISDIAL=SIP/107”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [dstring@macro-dial-one:8] GosubIf(“SIP/190.210.6.162-0000000e”, “1?zap2dahdi,1()”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [zap2dahdi@macro-dial-one:1] ExecIf(“SIP/190.210.6.162-0000000e”, “0?Return()”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [zap2dahdi@macro-dial-one:2] Set(“SIP/190.210.6.162-0000000e”, “NEWDIAL=”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [zap2dahdi@macro-dial-one:3] Set(“SIP/190.210.6.162-0000000e”, “LOOPCNT2=1”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [zap2dahdi@macro-dial-one:4] Set(“SIP/190.210.6.162-0000000e”, “ITER2=1”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [zap2dahdi@macro-dial-one:5] Set(“SIP/190.210.6.162-0000000e”, “THISPART2=SIP/107”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [zap2dahdi@macro-dial-one:6] ExecIf(“SIP/190.210.6.162-0000000e”, “0?Set(THISPART2=DAHDI/107)”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [zap2dahdi@macro-dial-one:7] Set(“SIP/190.210.6.162-0000000e”, “NEWDIAL=SIP/107&”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [zap2dahdi@macro-dial-one:8] Set(“SIP/190.210.6.162-0000000e”, “ITER2=2”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [zap2dahdi@macro-dial-one:9] GotoIf(“SIP/190.210.6.162-0000000e”, “0?begin2”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [zap2dahdi@macro-dial-one:10] Set(“SIP/190.210.6.162-0000000e”, “THISDIAL=SIP/107”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [zap2dahdi@macro-dial-one:11] Return(“SIP/190.210.6.162-0000000e”, “”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [dstring@macro-dial-one:9] Set(“SIP/190.210.6.162-0000000e”, “DSTRING=SIP/107&”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [dstring@macro-dial-one:10] Set(“SIP/190.210.6.162-0000000e”, “ITER=2”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [dstring@macro-dial-one:11] GotoIf(“SIP/190.210.6.162-0000000e”, “0?begin”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [dstring@macro-dial-one:12] Set(“SIP/190.210.6.162-0000000e”, “DSTRING=SIP/107”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [dstring@macro-dial-one:13] Return(“SIP/190.210.6.162-0000000e”, “”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-dial-one:27] GotoIf(“SIP/190.210.6.162-0000000e”, “0?nodial”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-dial-one:28] GotoIf(“SIP/190.210.6.162-0000000e”, “0?skiptrace”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-dial-one:29] GosubIf(“SIP/190.210.6.162-0000000e”, “1?ctset,1():ctclear,1()”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [ctset@macro-dial-one:1] Set(“SIP/190.210.6.162-0000000e”, “DB(CALLTRACE/107)=1156921341”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [ctset@macro-dial-one:2] Return(“SIP/190.210.6.162-0000000e”, “”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-dial-one:30] Set(“SIP/190.210.6.162-0000000e”, “D_OPTIONS=tr”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-dial-one:31] ExecIf(“SIP/190.210.6.162-0000000e”, “0?SIPAddHeader(Alert-Info: )”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-dial-one:32] ExecIf(“SIP/190.210.6.162-0000000e”, “0?SIPAddHeader()”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-dial-one:33] ExecIf(“SIP/190.210.6.162-0000000e”, “1?Set(CHANNEL(musicclass)=WIROOS)”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-dial-one:34] GosubIf(“SIP/190.210.6.162-0000000e”, “0?qwait,1()”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-dial-one:35] Set(“SIP/190.210.6.162-0000000e”, “__CWIGNORE=”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-dial-one:36] Set(“SIP/190.210.6.162-0000000e”, “__KEEPCID=TRUE”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-dial-one:37] GotoIf(“SIP/190.210.6.162-0000000e”, “0?usegoto,1”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-dial-one:38] GotoIf(“SIP/190.210.6.162-0000000e”, “1?godial”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Goto (macro-dial-one,s,42)
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-dial-one:42] Dial(“SIP/190.210.6.162-0000000e”, “SIP/107,15,tr”) in new stack
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] netsock2.c: == Using SIP RTP TOS bits 184
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] netsock2.c: == Using SIP RTP CoS mark 5
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] app_dial.c: – Called SIP/107
[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] app_dial.c: – SIP/107-0000000f is ringing
[2013-05-15 19:07:18] VERBOSE[28009][C-00000007] app_dial.c: – SIP/107-0000000f answered SIP/190.210.6.162-0000000e
[2013-05-15 19:07:27] VERBOSE[28009][C-00000007] pbx.c: – Executing [h@macro-dial-one:1] Macro(“SIP/190.210.6.162-0000000e”, “hangupcall,”) in new stack
[2013-05-15 19:07:27] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-hangupcall:1] GotoIf(“SIP/190.210.6.162-0000000e”, “1?theend”) in new stack
[2013-05-15 19:07:27] VERBOSE[28009][C-00000007] pbx.c: – Goto (macro-hangupcall,s,3)
[2013-05-15 19:07:27] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-hangupcall:3] ExecIf(“SIP/190.210.6.162-0000000e”, “0?Set(CDR(recordingfile)=)”) in new stack
[2013-05-15 19:07:27] VERBOSE[28009][C-00000007] pbx.c: – Executing [s@macro-hangupcall:4] Hangup(“SIP/190.210.6.162-0000000e”, “”) in new stack
[2013-05-15 19:07:27] VERBOSE[28009][C-00000007] app_macro.c: == Spawn extension (macro-hangupcall, s, 4) exited non-zero on ‘SIP/190.210.6.162-0000000e’ in macro ‘hangupcall’
[2013-05-15 19:07:27] VERBOSE[28009][C-00000007] pbx.c: == Spawn extension (macro-dial-one, h, 1) exited non-zero on ‘SIP/190.210.6.162-0000000e’
[2013-05-15 19:07:27] VERBOSE[28009][C-00000007] app_macro.c: == Spawn extension (macro-dial-one, s, 42) exited non-zero on ‘SIP/190.210.6.162-0000000e’ in macro ‘dial-one’
[2013-05-15 19:07:27] VERBOSE[28009][C-00000007] app_macro.c: == Spawn extension (macro-exten-vm, s, 14) exited non-zero on ‘SIP/190.210.6.162-0000000e’ in macro ‘exten-vm’
[2013-05-15 19:07:27] VERBOSE[28009][C-00000007] pbx.c: == Spawn extension (from-did-direct, 107, 2) exited non-zero on ‘SIP/190.210.6.162-0000000e’

3

[2013-05-15 19:01:49] VERBOSE[24924][C-00000004] pbx.c: – Executing [01153521491@from-trunk-sip-GWSIP1:1] Set(“SIP/190.210.6.162-00000008”, “GROUP()=OUT_23”) in new stack
[2013-05-15 19:01:49] VERBOSE[24924][C-00000004] pbx.c: – Executing [01153521491@from-trunk-sip-GWSIP1:2] Goto(“SIP/190.210.6.162-00000008”, “from-trunk,01153521491,1”) in new stack
[2013-05-15 19:01:49] VERBOSE[24924][C-00000004] pbx.c: – Goto (from-trunk,01153521491,1)
[2013-05-15 19:01:49] VERBOSE[24924][C-00000004] pbx.c: – Executing [01153521491@from-trunk:1] Set(“SIP/190.210.6.162-00000008”, “__FROM_DID=01153521491”) in new stack
[2013-05-15 19:01:49] VERBOSE[24924][C-00000004] pbx.c: – Executing [01153521491@from-trunk:2] Gosub(“SIP/190.210.6.162-00000008”, “app-blacklist-check,s,1()”) in new stack
[2013-05-15 19:01:49] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@app-blacklist-check:1] GotoIf(“SIP/190.210.6.162-00000008”, “0?blacklisted”) in new stack
[2013-05-15 19:01:49] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@app-blacklist-check:2] Set(“SIP/190.210.6.162-00000008”, “CALLED_BLACKLIST=1”) in new stack
[2013-05-15 19:01:49] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@app-blacklist-check:3] Return(“SIP/190.210.6.162-00000008”, “”) in new stack
[2013-05-15 19:01:49] VERBOSE[24924][C-00000004] pbx.c: – Executing [01153521491@from-trunk:3] Set(“SIP/190.210.6.162-00000008”, “CDR(did)=01153521491”) in new stack
[2013-05-15 19:01:49] VERBOSE[24924][C-00000004] pbx.c: – Executing [01153521491@from-trunk:4] ExecIf(“SIP/190.210.6.162-00000008”, “1 ?Set(CALLERID(name)=1156921341)”) in new stack
[2013-05-15 19:01:49] VERBOSE[24924][C-00000004] pbx.c: – Executing [01153521491@from-trunk:5] Set(“SIP/190.210.6.162-00000008”, “CHANNEL(musicclass)=WIROOS”) in new stack
[2013-05-15 19:01:49] VERBOSE[24924][C-00000004] pbx.c: – Executing [01153521491@from-trunk:6] Set(“SIP/190.210.6.162-00000008”, “__MOHCLASS=WIROOS”) in new stack
[2013-05-15 19:01:49] VERBOSE[24924][C-00000004] pbx.c: – Executing [01153521491@from-trunk:7] Set(“SIP/190.210.6.162-00000008”, “__CALLINGPRES_SV=allowed_not_screened”) in new stack
[2013-05-15 19:01:49] VERBOSE[24924][C-00000004] pbx.c: – Executing [01153521491@from-trunk:8] Set(“SIP/190.210.6.162-00000008”, “CALLERPRES()=allowed_not_screened”) in new stack
[2013-05-15 19:01:49] VERBOSE[24924][C-00000004] pbx.c: – Executing [01153521491@from-trunk:9] Goto(“SIP/190.210.6.162-00000008”, “timeconditions,3,1”) in new stack
[2013-05-15 19:01:49] VERBOSE[24924][C-00000004] pbx.c: – Goto (timeconditions,3,1)
[2013-05-15 19:01:49] VERBOSE[24924][C-00000004] pbx.c: – Executing [3@timeconditions:1] GotoIfTime(“SIP/190.210.6.162-00000008”, “00:00-23:59,,31-1,dec-jan?truestate") in new stack
[2013-05-15 19:01:49] VERBOSE[24924][C-00000004] pbx.c: – Executing [3@timeconditions:2] GotoIf(“SIP/190.210.6.162-00000008”, “0?truegoto”) in new stack
[2013-05-15 19:01:49] VERBOSE[24924][C-00000004] pbx.c: – Executing [3@timeconditions:3] ExecIf(“SIP/190.210.6.162-00000008”, “0?Set(DB(TC/3)=)”) in new stack
[2013-05-15 19:01:49] VERBOSE[24924][C-00000004] pbx.c: – Executing [3@timeconditions:4] GotoIf(“SIP/190.210.6.162-00000008”, “1?timeconditions,1,1”) in new stack
[2013-05-15 19:01:49] VERBOSE[24924][C-00000004] pbx.c: – Goto (timeconditions,1,1)
[2013-05-15 19:01:49] VERBOSE[24924][C-00000004] pbx.c: – Executing [1@timeconditions:1] GotoIfTime(“SIP/190.210.6.162-00000008”, "22:00-23:59,mon-fri,,?truestate") in new stack
[2013-05-15 19:01:49] VERBOSE[24924][C-00000004] pbx.c: – Executing [1@timeconditions:2] GotoIfTime(“SIP/190.210.6.162-00000008”, "00:00-08:00,mon-fri,,?truestate") in new stack
[2013-05-15 19:01:49] VERBOSE[24924][C-00000004] pbx.c: – Executing [1@timeconditions:3] GotoIfTime(“SIP/190.210.6.162-00000008”, "00:00-23:59,sat-sun,,*?truestate”) in new stack
[2013-05-15 19:01:49] VERBOSE[24924][C-00000004] pbx.c: – Executing [1@timeconditions:4] GotoIf(“SIP/190.210.6.162-00000008”, “0?truegoto”) in new stack
[2013-05-15 19:01:49] VERBOSE[24924][C-00000004] pbx.c: – Executing [1@timeconditions:5] ExecIf(“SIP/190.210.6.162-00000008”, “0?Set(DB(TC/1)=)”) in new stack
[2013-05-15 19:01:49] VERBOSE[24924][C-00000004] pbx.c: – Executing [1@timeconditions:6] GotoIf(“SIP/190.210.6.162-00000008”, “1?ivr-2,s,1”) in new stack
[2013-05-15 19:01:49] VERBOSE[24924][C-00000004] pbx.c: – Goto (ivr-2,s,1)
[2013-05-15 19:01:49] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@ivr-2:1] Set(“SIP/190.210.6.162-00000008”, “_IVR_CONTEXT_ivr-2=”) in new stack
[2013-05-15 19:01:49] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@ivr-2:2] Set(“SIP/190.210.6.162-00000008”, “_IVR_CONTEXT=ivr-2”) in new stack
[2013-05-15 19:01:49] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@ivr-2:3] Set(“SIP/190.210.6.162-00000008”, “__IVR_RETVM=”) in new stack
[2013-05-15 19:01:49] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@ivr-2:4] GotoIf(“SIP/190.210.6.162-00000008”, “0?skip”) in new stack
[2013-05-15 19:01:49] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@ivr-2:5] Answer(“SIP/190.210.6.162-00000008”, “”) in new stack
[2013-05-15 19:01:49] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@ivr-2:6] Wait(“SIP/190.210.6.162-00000008”, “1”) in new stack
[2013-05-15 19:01:50] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@ivr-2:7] Set(“SIP/190.210.6.162-00000008”, “IVR_MSG=custom/WIROOS-IVR”) in new stack
[2013-05-15 19:01:50] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@ivr-2:8] Set(“SIP/190.210.6.162-00000008”, “TIMEOUT(digit)=3”) in new stack
[2013-05-15 19:01:50] VERBOSE[24924][C-00000004] func_timeout.c: – Digit timeout set to 3.000
[2013-05-15 19:01:50] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@ivr-2:9] ExecIf(“SIP/190.210.6.162-00000008”, “1?Background(custom/WIROOS-IVR)”) in new stack
[2013-05-15 19:01:50] VERBOSE[24924][C-00000004] file.c: – <SIP/190.210.6.162-00000008> Playing ‘custom/WIROOS-IVR.gsm’ (language ‘en’)
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: == CDR updated on SIP/190.210.6.162-00000008
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [1@ivr-2:1] Goto(“SIP/190.210.6.162-00000008”, “ext-queues,302,1”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Goto (ext-queues,302,1)
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [302@ext-queues:1] Macro(“SIP/190.210.6.162-00000008”, “user-callerid,”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@macro-user-callerid:1] Set(“SIP/190.210.6.162-00000008”, “TOUCH_MONITOR=1368655309.24”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@macro-user-callerid:2] Set(“SIP/190.210.6.162-00000008”, “AMPUSER=1156921341”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@macro-user-callerid:3] GotoIf(“SIP/190.210.6.162-00000008”, “0?report”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@macro-user-callerid:4] ExecIf(“SIP/190.210.6.162-00000008”, “1?Set(REALCALLERIDNUM=1156921341)”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@macro-user-callerid:5] Set(“SIP/190.210.6.162-00000008”, “AMPUSER=”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@macro-user-callerid:6] Set(“SIP/190.210.6.162-00000008”, “AMPUSERCIDNAME=”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@macro-user-callerid:7] GotoIf(“SIP/190.210.6.162-00000008”, “1?report”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Goto (macro-user-callerid,s,15)
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@macro-user-callerid:15] GotoIf(“SIP/190.210.6.162-00000008”, “0?continue”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@macro-user-callerid:16] Set(“SIP/190.210.6.162-00000008”, “__TTL=64”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@macro-user-callerid:17] GotoIf(“SIP/190.210.6.162-00000008”, “1?continue”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Goto (macro-user-callerid,s,28)
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@macro-user-callerid:28] Set(“SIP/190.210.6.162-00000008”, “CALLERID(number)=1156921341”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@macro-user-callerid:29] Set(“SIP/190.210.6.162-00000008”, “CALLERID(name)=1156921341”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@macro-user-callerid:30] Set(“SIP/190.210.6.162-00000008”, “CDR(cnum)=1156921341”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@macro-user-callerid:31] Set(“SIP/190.210.6.162-00000008”, “CDR(cnam)=1156921341”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@macro-user-callerid:32] Set(“SIP/190.210.6.162-00000008”, “CHANNEL(language)=en”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [302@ext-queues:2] Answer(“SIP/190.210.6.162-00000008”, “”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [302@ext-queues:3] Macro(“SIP/190.210.6.162-00000008”, “blkvm-set,reset”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@macro-blkvm-set:1] ExecIf(“SIP/190.210.6.162-00000008”, “1?Set(__BLKVM_CHANNEL=SIP/190.210.6.162-00000008)”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@macro-blkvm-set:2] Set(“SIP/190.210.6.162-00000008”, “SHARED(BLKVM,SIP/190.210.6.162-00000008)=TRUE”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@macro-blkvm-set:3] Set(“SIP/190.210.6.162-00000008”, “GOSUB_RETVAL=TRUE”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@macro-blkvm-set:4] MacroExit(“SIP/190.210.6.162-00000008”, “”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [302@ext-queues:4] ExecIf(“SIP/190.210.6.162-00000008”, “1?Set(_DIAL_OPTIONS=trM(auto-blkvm))”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [302@ext-queues:5] Set(“SIP/190.210.6.162-00000008”, “__NODEST=302”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [302@ext-queues:6] Set(“SIP/190.210.6.162-00000008”, “QCIDPP=”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [302@ext-queues:7] ExecIf(“SIP/190.210.6.162-00000008”, “0?Macro(prepend-cid, )”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [302@ext-queues:8] Set(“SIP/190.210.6.162-00000008”, “QAINFO=”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [302@ext-queues:9] ExecIf(“SIP/190.210.6.162-00000008”, “0?Set(__ALERT_INFO=)”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [302@ext-queues:10] Set(“SIP/190.210.6.162-00000008”, “QJOINMSG=”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [302@ext-queues:11] Set(“SIP/190.210.6.162-00000008”, “QMOH=WIROOS”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [302@ext-queues:12] ExecIf(“SIP/190.210.6.162-00000008”, “1?Set(__MOHCLASS=WIROOS)”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [302@ext-queues:13] Set(“SIP/190.210.6.162-00000008”, “QRETRY=”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [302@ext-queues:14] Set(“SIP/190.210.6.162-00000008”, “QOPTIONS=t”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [302@ext-queues:15] Set(“SIP/190.210.6.162-00000008”, “QAGI=”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [302@ext-queues:16] Set(“SIP/190.210.6.162-00000008”, “QRULE=”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [302@ext-queues:17] Set(“SIP/190.210.6.162-00000008”, “QPOSITION=”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [302@ext-queues:18] Gosub(“SIP/190.210.6.162-00000008”, “sub-record-check,s,1(q,302,dontcare)”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@sub-record-check:1] Set(“SIP/190.210.6.162-00000008”, “REC_POLICY_MODE_SAVE=”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@sub-record-check:2] GotoIf(“SIP/190.210.6.162-00000008”, “1?check”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Goto (sub-record-check,s,7)
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@sub-record-check:7] Set(“SIP/190.210.6.162-00000008”, “__MON_FMT=wav”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@sub-record-check:8] GotoIf(“SIP/190.210.6.162-00000008”, “1?next”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Goto (sub-record-check,s,11)
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@sub-record-check:11] ExecIf(“SIP/190.210.6.162-00000008”, “0?Return()”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@sub-record-check:12] ExecIf(“SIP/190.210.6.162-00000008”, “1?Set(__REC_POLICY_MODE=dontcare)”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@sub-record-check:13] GotoIf(“SIP/190.210.6.162-00000008”, “0?q,1”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@sub-record-check:14] Set(“SIP/190.210.6.162-00000008”, “__REC_STATUS=INITIALIZED”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@sub-record-check:15] Set(“SIP/190.210.6.162-00000008”, “NOW=1368655320”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@sub-record-check:16] Set(“SIP/190.210.6.162-00000008”, “__DAY=15”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@sub-record-check:17] Set(“SIP/190.210.6.162-00000008”, “__MONTH=05”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@sub-record-check:18] Set(“SIP/190.210.6.162-00000008”, “__YEAR=2013”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@sub-record-check:19] Set(“SIP/190.210.6.162-00000008”, “__TIMESTR=20130515-190200”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@sub-record-check:20] Set(“SIP/190.210.6.162-00000008”, “__FROMEXTEN=1156921341”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@sub-record-check:21] Set(“SIP/190.210.6.162-00000008”, “__CALLFILENAME=q-302-1156921341-20130515-190200-1368655309.24”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@sub-record-check:22] Goto(“SIP/190.210.6.162-00000008”, “q,1”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Goto (sub-record-check,q,1)
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [q@sub-record-check:1] GosubIf(“SIP/190.210.6.162-00000008”, “0?recq,1(q,302,1156921341)”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [q@sub-record-check:2] Return(“SIP/190.210.6.162-00000008”, “”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [302@ext-queues:19] ExecIf(“SIP/190.210.6.162-00000008”, “0?Playback(, )”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [302@ext-queues:20] QueueLog(“SIP/190.210.6.162-00000008”, “302,1368655309.24,NONE,DID,01153521491”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [302@ext-queues:21] Set(“SIP/190.210.6.162-00000008”, “QAANNOUNCE=”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] pbx.c: – Executing [302@ext-queues:22] Queue(“SIP/190.210.6.162-00000008”, “302,t,1800,”) in new stack
[2013-05-15 19:02:00] VERBOSE[24924][C-00000004] res_musiconhold.c: – Started music on hold, class ‘WIROOS’, on SIP/190.210.6.162-00000008
[2013-05-15 19:02:01] VERBOSE[24924][C-00000004] app_queue.c: – Local/107@from-queue-00000009;1 is ringing
[2013-05-15 19:02:01] VERBOSE[24924][C-00000004] app_queue.c: – Local/107@from-queue-00000009;1 connected line has changed. Saving it until answer for SIP/190.210.6.162-00000008
[2013-05-15 19:02:01] VERBOSE[24924][C-00000004] app_queue.c: – Local/107@from-queue-00000009;1 connected line has changed. Saving it until answer for SIP/190.210.6.162-00000008
[2013-05-15 19:02:01] VERBOSE[24924][C-00000004] app_queue.c: – Local/106@from-queue-00000008;1 answered SIP/190.210.6.162-00000008
[2013-05-15 19:02:01] VERBOSE[24924][C-00000004] res_musiconhold.c: – Stopped music on hold on SIP/190.210.6.162-00000008
[2013-05-15 19:02:33] VERBOSE[24924][C-00000004] pbx.c: – Executing [h@ext-queues:1] Macro(“SIP/190.210.6.162-00000008”, “hangupcall,”) in new stack
[2013-05-15 19:02:33] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@macro-hangupcall:1] GotoIf(“SIP/190.210.6.162-00000008”, “1?theend”) in new stack
[2013-05-15 19:02:33] VERBOSE[24924][C-00000004] pbx.c: – Goto (macro-hangupcall,s,3)
[2013-05-15 19:02:33] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@macro-hangupcall:3] ExecIf(“SIP/190.210.6.162-00000008”, “0?Set(CDR(recordingfile)=)”) in new stack
[2013-05-15 19:02:33] VERBOSE[24924][C-00000004] pbx.c: – Executing [s@macro-hangupcall:4] Hangup(“SIP/190.210.6.162-00000008”, “”) in new stack
[2013-05-15 19:02:33] VERBOSE[24924][C-00000004] app_macro.c: == Spawn extension (macro-hangupcall, s, 4) exited non-zero on ‘SIP/190.210.6.162-00000008’ in macro ‘hangupcall’
[2013-05-15 19:02:33] VERBOSE[24924][C-00000004] pbx.c: == Spawn extension (ext-queues, h, 1) exited non-zero on ‘SIP/190.210.6.162-00000008’
[2013-05-15 19:02:33] VERBOSE[24924][C-00000004] pbx.c: == Spawn extension (ext-queues, 302, 22) exited non-zero on ‘SIP/190.210.6.162-00000008’

4

I think this log is a bit overwhelming! I do notice you say the call is “automatically hanged up” but the log file shows the call was answered and then hung up 30 seconds later. Is anything happening in that 30 seconds?

[2013-05-15 19:02:01] VERBOSE[24924][C-00000004] app_queue.c: -- Local/106@from-queue-00000008;1 answered SIP/190.210.6.162-00000008
[2013-05-15 19:02:01] VERBOSE[24924][C-00000004] res_musiconhold.c: -- Stopped music on hold on SIP/190.210.6.162-00000008
[2013-05-15 19:02:33] VERBOSE[24924][C-00000004] pbx.c: -- Executing [h@ext-queues:1] Macro("SIP/190.210.6.162-00000008", "hangupcall,") in new stack
5

Sorry for the log, I wasn’t sure about which part was interesting about it and which one weren’t.

The operator picks up the phone, but it’s not connected.

The user calling starts hearing the IVR again and the operator talks to no-one. When the timeout of the IVR is reached, the call is transfered again and it’s the same process.

The wierd thing is that the operator who actually picked up was the 107, and not the 106 (although both of them are on the same queue).

Here’s the log for when he picks up the phone and hears nothing, I was on the other end and at the same time the IVR started playing again.

[2013-05-15 19:07:07] VERBOSE[28009][C-00000007] app_dial.c: – SIP/107-0000000f is ringing
[2013-05-15 19:07:18] VERBOSE[28009][C-00000007] app_dial.c: – SIP/107-0000000f answered SIP/190.210.6.162-0000000e
[2013-05-15 19:07:27] VERBOSE[28009][C-00000007] pbx.c: – Executing [h@macro-dial-one:1] Macro(“SIP/190.210.6.162-0000000e”, “hangupcall,”) in new stack

6

Hi,
Apologies for jumping in here but this is the same issue as per the post i added to earlier today. Queques error after update core and framework 2.11

This has to be a bug, now reported by three different people

http://www.freepbx.org/forum/general-help/queques-error-after-update-core-and-framework-211