Queues, Join Announcements, and Do Not Disturb

[reinigerjm]

So, first, the version numbers:
FreePBX v2.11.0.37
Asterisk 11.7.0

The situation:

We have set up a Queue for our customer service team with 6 static agents. Here’s the config section for the Queue:

announce-frequency=45
announce-holdtime=yes
announce-position=no
autofill=yes
autopause=no
autopausebusy=no
autopausedelay=0
autopauseunavail=no
eventmemberstatus=yes
eventwhencalled=yes
joinempty=yes
leavewhenempty=no
maxlen=0
memberdelay=0
music=ToddPiano
penaltymemberslimit=0
periodic-announce-frequency=0
queue-callswaiting=silence/1
queue-thereare=silence/1
queue-youarenext=silence/1
reportholdtime=no
retry=5
ringinuse=no
servicelevel=60
setinterfacevar=yes
strategy=ringall
timeout=30
timeoutpriority=app
timeoutrestart=no
weight=0
wrapuptime=5

If all phones are busy, the system is supposed to play a Join Announcement and place them in queue. However, if we are short-handed and only have 4 people to answer phones and the empty phones are placed on Do Not Disturb (either via the phone’s softkey OR via the FreePBX Feature Code), customers who dial in and get placed in the queue do not hear the Join Announcement; instead it goes straight to estimated hold time and then MOH.

If all 6 agent phones are actively engaged in a phone call, then the Join Announcement plays normally.

My solution for now was to remove the phones as static agents and have customer service employees log their phones into and out of the queue when they come and go. For their sake, I’d love for them to be able to just hit the DND key on their phones when they want to take a break, instead of having to logout/login every time they use the restroom or grab a drink.

Any thoughts? Further information I can dig up to help?

[jfinstrom (James Finstrom)]

Can you provide a call trace of a call acting in the above manner.

[reinigerjm]

I set up a test queue with a single dynamic agent, ext 2006, being called in various states by an internal extension 5440. The results are the same whether it comes from an outside call or another extension inside the office, so for simplicity I’m just using multiple internal extensions. All phones are either Linksys SPA942s or their new incarnation the Cisco SPA504G

This first call trace is the calling the queue while 2006 is already in a call. The Join Announcement plays normally here:

[2014-05-14 15:31:10] VERBOSE[1919][C-00000bfb] netsock2.c: == Using SIP RTP TOS bits 184 [2014-05-14 15:31:10] VERBOSE[1919][C-00000bfb] netsock2.c: == Using SIP RTP CoS mark 5 [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:1] Macro("SIP/5440-00004dae", "user-callerid,") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:1] Set("SIP/5440-00004dae", "TOUCH_MONITOR=1400099470.42008") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:2] Set("SIP/5440-00004dae", "AMPUSER=5440") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:3] GotoIf("SIP/5440-00004dae", "0?report") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:4] ExecIf("SIP/5440-00004dae", "1?Set(REALCALLERIDNUM=5440)") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:5] Set("SIP/5440-00004dae", "AMPUSER=5440") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:6] GotoIf("SIP/5440-00004dae", "0?limit") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:7] Set("SIP/5440-00004dae", "AMPUSERCIDNAME=Emporium") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:8] GotoIf("SIP/5440-00004dae", "0?report") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:9] Set("SIP/5440-00004dae", "AMPUSERCID=5440") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:10] Set("SIP/5440-00004dae", "__DIAL_OPTIONS=Ttr") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:11] Set("SIP/5440-00004dae", "CALLERID(all)="Emporium" <5440>") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:12] GotoIf("SIP/5440-00004dae", "0?limit") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:13] ExecIf("SIP/5440-00004dae", "0?Set(GROUP(concurrency_limit)=5440)") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:14] ExecIf("SIP/5440-00004dae", "0?Set(CHANNEL(language)=)") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:15] GosubIf("SIP/5440-00004dae", "7?sub-ccss,s,1(from-internal,9999)") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:1] ExecIf("SIP/5440-00004dae", "0?Return()") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:2] Set("SIP/5440-00004dae", "CCSS_SETUP=TRUE") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:3] GosubIf("SIP/5440-00004dae", "0?monitor_config,1(from-internal,9999):monitor_default,1(from-internal,9999)") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:1] GotoIf("SIP/5440-00004dae", "0?is_exten") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:2] StackPop("SIP/5440-00004dae", "") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:3] Return("SIP/5440-00004dae", "FALSE") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:16] GotoIf("SIP/5440-00004dae", "0?continue") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:17] Set("SIP/5440-00004dae", "__TTL=64") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:18] GotoIf("SIP/5440-00004dae", "1?continue") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Goto (macro-user-callerid,s,29) [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:29] Set("SIP/5440-00004dae", "CALLERID(number)=5440") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:30] Set("SIP/5440-00004dae", "CALLERID(name)=Emporium") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:31] Set("SIP/5440-00004dae", "CDR(cnum)=5440") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:32] Set("SIP/5440-00004dae", "CDR(cnam)=Emporium") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:33] Set("SIP/5440-00004dae", "CHANNEL(language)=en") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:2] Answer("SIP/5440-00004dae", "") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:3] Macro("SIP/5440-00004dae", "blkvm-set,reset") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:1] ExecIf("SIP/5440-00004dae", "1?Set(__BLKVM_CHANNEL=SIP/5440-00004dae)") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:2] Set("SIP/5440-00004dae", "SHARED(BLKVM,SIP/5440-00004dae)=TRUE") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:3] Set("SIP/5440-00004dae", "GOSUB_RETVAL=TRUE") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]-set:4] MacroExit("SIP/5440-00004dae", "") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:4] ExecIf("SIP/5440-00004dae", "1?Set(_DIAL_OPTIONS=TtrM(auto-blkvm))") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:5] Set("SIP/5440-00004dae", "__NODEST=9999") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:6] Set("SIP/5440-00004dae", "QCIDPP=") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:7] Set("SIP/5440-00004dae", "VQ_CIDPP=") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:8] ExecIf("SIP/5440-00004dae", "0?Macro(prepend-cid,)") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:9] Set("SIP/5440-00004dae", "QAINFO=") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:10] Set("SIP/5440-00004dae", "VQ_AINFO=") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:11] ExecIf("SIP/5440-00004dae", "0?Set(__ALERT_INFO=)") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:12] Set("SIP/5440-00004dae", "QJOINMSG=custom/RedFrogQueueJoin") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:13] Set("SIP/5440-00004dae", "VQ_JOINMSG=") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:14] Set("SIP/5440-00004dae", "QMOH=ToddPiano") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:15] Set("SIP/5440-00004dae", "VQ_MOH=") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:16] ExecIf("SIP/5440-00004dae", "1?Set(__MOHCLASS=ToddPiano)") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:17] ExecIf("SIP/5440-00004dae", "1?Set(CHANNEL(musicclass)=ToddPiano)") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:18] Set("SIP/5440-00004dae", "QRINGOPTS=R") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:19] Set("SIP/5440-00004dae", "QRETRY=") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:20] Set("SIP/5440-00004dae", "VQ_RETRY=") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:21] Set("SIP/5440-00004dae", "QOPTIONS=tR") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:22] Set("SIP/5440-00004dae", "VQ_OPTIONS=") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:23] Set("SIP/5440-00004dae", "QGOSUB=") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:24] Set("SIP/5440-00004dae", "VQ_GOSUB=") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:25] Set("SIP/5440-00004dae", "QAGI=") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:26] Set("SIP/5440-00004dae", "VQ_AGI=") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:27] Set("SIP/5440-00004dae", "QRULE=") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:28] Set("SIP/5440-00004dae", "VQ_RULE=") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:29] Set("SIP/5440-00004dae", "QPOSITION=") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:30] Set("SIP/5440-00004dae", "VQ_POSITION=") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:31] Gosub("SIP/5440-00004dae", "sub-record-check,s,1(q,9999,dontcare)") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:1] Set("SIP/5440-00004dae", "REC_POLICY_MODE_SAVE=") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:2] GotoIf("SIP/5440-00004dae", "1?check") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Goto (sub-record-check,s,7) [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:7] Set("SIP/5440-00004dae", "__MON_FMT=wav") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:8] GotoIf("SIP/5440-00004dae", "1?next") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Goto (sub-record-check,s,11) [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:11] ExecIf("SIP/5440-00004dae", "0?Return()") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:12] ExecIf("SIP/5440-00004dae", "1?Set(__REC_POLICY_MODE=dontcare)") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:13] GotoIf("SIP/5440-00004dae", "0?q,1") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:14] Set("SIP/5440-00004dae", "__REC_STATUS=INITIALIZED") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:15] Set("SIP/5440-00004dae", "NOW=1400099470") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:16] Set("SIP/5440-00004dae", "__DAY=14") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:17] Set("SIP/5440-00004dae", "__MONTH=05") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:18] Set("SIP/5440-00004dae", "__YEAR=2014") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:19] Set("SIP/5440-00004dae", "__TIMESTR=20140514-153110") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:20] Set("SIP/5440-00004dae", "__FROMEXTEN=5440") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:21] Set("SIP/5440-00004dae", "__CALLFILENAME=q-9999-5440-20140514-153110-1400099470.42008") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:22] Goto("SIP/5440-00004dae", "q,1") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Goto (sub-record-check,q,1) [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:1] GosubIf("SIP/5440-00004dae", "0?recq,1(q,9999,5440)") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:2] Return("SIP/5440-00004dae", "") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:32] Set("SIP/5440-00004dae", "__CWIGNORE=TRUE") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [[email protected]:33] ExecIf("SIP/5440-00004dae", "1?Playback(custom/RedFrogQueueJoin, )") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] file.c: -- Playing 'custom/RedFrogQueueJoin.slin' (language 'en')

[2014-05-14 15:31:42] VERBOSE[13352][C-00000bfb] pbx.c: – Executing [[email protected]:34] QueueLog(“SIP/5440-00004dae”, “9999,1400099470.42008,NONE,DID,”) in new stack
[2014-05-14 15:31:42] VERBOSE[13352][C-00000bfb] pbx.c: – Executing [[email protected]:35] Set(“SIP/5440-00004dae”, “QAANNOUNCE=”) in new stack
[2014-05-14 15:31:42] VERBOSE[13352][C-00000bfb] pbx.c: – Executing [[email protected]:36] Set(“SIP/5440-00004dae”, “VQ_AANNOUNCE=”) in new stack
[2014-05-14 15:31:42] VERBOSE[13352][C-00000bfb] pbx.c: – Executing [[email protected]:37] Set(“SIP/5440-00004dae”, “QMAXWAIT=”) in new stack
[2014-05-14 15:31:42] VERBOSE[13352][C-00000bfb] pbx.c: – Executing [[email protected]:38] Set(“SIP/5440-00004dae”, “VQ_MAXWAIT=”) in new stack
[2014-05-14 15:31:42] VERBOSE[13352][C-00000bfb] pbx.c: – Executing [[email protected]:39] Queue(“SIP/5440-00004dae”, “9999,tR,”) in new stack
[2014-05-14 15:31:42] VERBOSE[13352][C-00000bfb] res_musiconhold.c: – Started music on hold, class ‘ToddPiano’, on SIP/5440-00004dae
[2014-05-14 15:31:42] VERBOSE[13352][C-00000bfb] res_musiconhold.c: – Stopped music on hold on SIP/5440-00004dae
[2014-05-14 15:31:42] VERBOSE[13352][C-00000bfb] app_queue.c: – Hold time for 9999 is 0 minute(s) 0 seconds
[2014-05-14 15:31:42] VERBOSE[13352][C-00000bfb] app_queue.c: – Told SIP/5440-00004dae in 9999 their queue position (which was 1)
[2014-05-14 15:31:42] VERBOSE[13352][C-00000bfb] file.c: – <SIP/5440-00004dae> Playing ‘queue-thankyou.ulaw’ (language ‘en’)
[2014-05-14 15:31:44] VERBOSE[13352][C-00000bfb] res_musiconhold.c: – Started music on hold, class ‘ToddPiano’, on SIP/5440-00004dae

This is the trace with the agent device set to Do Not Disturb via the phone’s soft key. The Join Announcement does NOT play:

[2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:1] Macro("SIP/5440-00004dd0", "user-callerid,") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:1] Set("SIP/5440-00004dd0", "TOUCH_MONITOR=1400099853.42042") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:2] Set("SIP/5440-00004dd0", "AMPUSER=5440") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:3] GotoIf("SIP/5440-00004dd0", "0?report") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:4] ExecIf("SIP/5440-00004dd0", "1?Set(REALCALLERIDNUM=5440)") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:5] Set("SIP/5440-00004dd0", "AMPUSER=5440") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:6] GotoIf("SIP/5440-00004dd0", "0?limit") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:7] Set("SIP/5440-00004dd0", "AMPUSERCIDNAME=Emporium") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:8] GotoIf("SIP/5440-00004dd0", "0?report") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:9] Set("SIP/5440-00004dd0", "AMPUSERCID=5440") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:10] Set("SIP/5440-00004dd0", "__DIAL_OPTIONS=Ttr") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:11] Set("SIP/5440-00004dd0", "CALLERID(all)="Emporium" <5440>") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:12] GotoIf("SIP/5440-00004dd0", "0?limit") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:13] ExecIf("SIP/5440-00004dd0", "0?Set(GROUP(concurrency_limit)=5440)") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:14] ExecIf("SIP/5440-00004dd0", "0?Set(CHANNEL(language)=)") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:15] GosubIf("SIP/5440-00004dd0", "7?sub-ccss,s,1(from-internal,9999)") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:1] ExecIf("SIP/5440-00004dd0", "0?Return()") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:2] Set("SIP/5440-00004dd0", "CCSS_SETUP=TRUE") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:3] GosubIf("SIP/5440-00004dd0", "0?monitor_config,1(from-internal,9999):monitor_default,1(from-internal,9999)") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:1] GotoIf("SIP/5440-00004dd0", "0?is_exten") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:2] StackPop("SIP/5440-00004dd0", "") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:3] Return("SIP/5440-00004dd0", "FALSE") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:16] GotoIf("SIP/5440-00004dd0", "0?continue") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:17] Set("SIP/5440-00004dd0", "__TTL=64") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:18] GotoIf("SIP/5440-00004dd0", "1?continue") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Goto (macro-user-callerid,s,29) [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:29] Set("SIP/5440-00004dd0", "CALLERID(number)=5440") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:30] Set("SIP/5440-00004dd0", "CALLERID(name)=Emporium") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:31] Set("SIP/5440-00004dd0", "CDR(cnum)=5440") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:32] Set("SIP/5440-00004dd0", "CDR(cnam)=Emporium") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:33] Set("SIP/5440-00004dd0", "CHANNEL(language)=en") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:2] Answer("SIP/5440-00004dd0", "") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:3] Macro("SIP/5440-00004dd0", "blkvm-set,reset") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:1] ExecIf("SIP/5440-00004dd0", "1?Set(__BLKVM_CHANNEL=SIP/5440-00004dd0)") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:2] Set("SIP/5440-00004dd0", "SHARED(BLKVM,SIP/5440-00004dd0)=TRUE") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:3] Set("SIP/5440-00004dd0", "GOSUB_RETVAL=TRUE") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:4] MacroExit("SIP/5440-00004dd0", "") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:4] ExecIf("SIP/5440-00004dd0", "1?Set(_DIAL_OPTIONS=TtrM(auto-blkvm))") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:5] Set("SIP/5440-00004dd0", "__NODEST=9999") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:6] Set("SIP/5440-00004dd0", "QCIDPP=") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:7] Set("SIP/5440-00004dd0", "VQ_CIDPP=") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:8] ExecIf("SIP/5440-00004dd0", "0?Macro(prepend-cid,)") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:9] Set("SIP/5440-00004dd0", "QAINFO=") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:10] Set("SIP/5440-00004dd0", "VQ_AINFO=") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:11] ExecIf("SIP/5440-00004dd0", "0?Set(__ALERT_INFO=)") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:12] Set("SIP/5440-00004dd0", "QJOINMSG=custom/RedFrogQueueJoin") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:13] Set("SIP/5440-00004dd0", "VQ_JOINMSG=") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:14] Set("SIP/5440-00004dd0", "QMOH=ToddPiano") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:15] Set("SIP/5440-00004dd0", "VQ_MOH=") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:16] ExecIf("SIP/5440-00004dd0", "1?Set(__MOHCLASS=ToddPiano)") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:17] ExecIf("SIP/5440-00004dd0", "1?Set(CHANNEL(musicclass)=ToddPiano)") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:18] Set("SIP/5440-00004dd0", "QRINGOPTS=R") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:19] Set("SIP/5440-00004dd0", "QRETRY=") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:20] Set("SIP/5440-00004dd0", "VQ_RETRY=") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:21] Set("SIP/5440-00004dd0", "QOPTIONS=tR") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:22] Set("SIP/5440-00004dd0", "VQ_OPTIONS=") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:23] Set("SIP/5440-00004dd0", "QGOSUB=") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:24] Set("SIP/5440-00004dd0", "VQ_GOSUB=") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:25] Set("SIP/5440-00004dd0", "QAGI=") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:26] Set("SIP/5440-00004dd0", "VQ_AGI=") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:27] Set("SIP/5440-00004dd0", "QRULE=") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:28] Set("SIP/5440-00004dd0", "VQ_RULE=") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:29] Set("SIP/5440-00004dd0", "QPOSITION=") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:30] Set("SIP/5440-00004dd0", "VQ_POSITION=") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:31] Gosub("SIP/5440-00004dd0", "sub-record-check,s,1(q,9999,dontcare)") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:1] Set("SIP/5440-00004dd0", "REC_POLICY_MODE_SAVE=") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:2] GotoIf("SIP/5440-00004dd0", "1?check") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Goto (sub-record-check,s,7) [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:7] Set("SIP/5440-00004dd0", "__MON_FMT=wav") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:8] GotoIf("SIP/5440-00004dd0", "1?next") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Goto (sub-record-check,s,11) [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:11] ExecIf("SIP/5440-00004dd0", "0?Return()") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:12] ExecIf("SIP/5440-00004dd0", "1?Set(__REC_POLICY_MODE=dontcare)") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:13] GotoIf("SIP/5440-00004dd0", "0?q,1") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:14] Set("SIP/5440-00004dd0", "__REC_STATUS=INITIALIZED") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:15] Set("SIP/5440-00004dd0", "NOW=1400099853") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:16] Set("SIP/5440-00004dd0", "__DAY=14") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:17] Set("SIP/5440-00004dd0", "__MONTH=05") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:18] Set("SIP/5440-00004dd0", "__YEAR=2014") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:19] Set("SIP/5440-00004dd0", "__TIMESTR=20140514-153733") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:20] Set("SIP/5440-00004dd0", "__FROMEXTEN=5440") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:21] Set("SIP/5440-00004dd0", "__CALLFILENAME=q-9999-5440-20140514-153733-1400099853.42042") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:22] Goto("SIP/5440-00004dd0", "q,1") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Goto (sub-record-check,q,1) [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:1] GosubIf("SIP/5440-00004dd0", "0?recq,1(q,9999,5440)") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:2] Return("SIP/5440-00004dd0", "") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:32] Set("SIP/5440-00004dd0", "__CWIGNORE=TRUE") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:33] ExecIf("SIP/5440-00004dd0", "0?Playback(custom/RedFrogQueueJoin, )") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:34] QueueLog("SIP/5440-00004dd0", "9999,1400099853.42042,NONE,DID,") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:35] Set("SIP/5440-00004dd0", "QAANNOUNCE=") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:36] Set("SIP/5440-00004dd0", "VQ_AANNOUNCE=") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:37] Set("SIP/5440-00004dd0", "QMAXWAIT=") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:38] Set("SIP/5440-00004dd0", "VQ_MAXWAIT=") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [[email protected]:39] Queue("SIP/5440-00004dd0", "9999,tR,,,,,,,,") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] res_musiconhold.c: -- Started music on hold, class 'ToddPiano', on SIP/5440-00004dd0 [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:1] Set("Local/[email protected];2", "QAGENT=2006") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] app_queue.c: -- Called Local/[email protected]/n [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] app_queue.c: -- LazyMembers debugging - Numbusies: 0, Numnoans: 0, Nummems: 1 [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:2] Goto("Local/[email protected];2", "9999,1") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Goto (from-queue,9999,1) [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:1] Goto("Local/[email protected];2", "from-internal,2006,1") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Goto (from-internal,2006,1) [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:1] Set("Local/[email protected];2", "__RINGTIMER=15") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:2] Macro("Local/[email protected];2", "exten-vm,novm,2006,0,0,0") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:1] Macro("Local/[email protected];2", "user-callerid,") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:1] Set("Local/[email protected];2", "TOUCH_MONITOR=1400099853.42044") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:2] Set("Local/[email protected];2", "AMPUSER=5440") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:3] GotoIf("Local/[email protected];2", "1?report") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Goto (macro-user-callerid,s,16) [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:16] GotoIf("Local/[email protected];2", "0?continue") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:17] Set("Local/[email protected];2", "__TTL=63") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:18] GotoIf("Local/[email protected];2", "1?continue") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Goto (macro-user-callerid,s,29) [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:29] Set("Local/[email protected];2", "CALLERID(number)=5440") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:30] Set("Local/[email protected];2", "CALLERID(name)=Emporium") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:31] Set("Local/[email protected];2", "CDR(cnum)=5440") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:32] Set("Local/[email protected];2", "CDR(cnam)=Emporium") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:33] Set("Local/[email protected];2", "CHANNEL(language)=en") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:2] Set("Local/[email protected];2", "RingGroupMethod=none") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:3] Set("Local/[email protected];2", "__EXTTOCALL=2006") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:4] Set("Local/[email protected];2", "__PICKUPMARK=2006") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:5] Set("Local/[email protected];2", "RT=") in new stack [2014-05-14 15:37:33] WARNING[13397][C-00000c06] chan_sip.c: This function can only be used on SIP channels. [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:6] ExecIf("Local/[email protected];2", "0?Macro(vm,novm,DIRECTDIAL,)") in new stack [2014-05-14 15:37:33] WARNING[13397][C-00000c06] chan_sip.c: This function can only be used on SIP channels. [2014-05-14 15:37:33] WARNING[13397][C-00000c06] chan_sip.c: This function can only be used on SIP channels. [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:7] ExecIf("Local/[email protected];2", "0?MacroExit()") in new stack [2014-05-14 15:37:33] WARNING[13397][C-00000c06] chan_sip.c: This function can only be used on SIP channels. [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:8] Gosub("Local/[email protected];2", "sub-record-check,s,1(exten,2006,)") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:1] Set("Local/[email protected];2", "REC_POLICY_MODE_SAVE=dontcare") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:2] GotoIf("Local/[email protected];2", "1?check") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Goto (sub-record-check,s,7) [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:7] Set("Local/[email protected];2", "__MON_FMT=wav") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:8] GotoIf("Local/[email protected];2", "1?next") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Goto (sub-record-check,s,11) [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:11] ExecIf("Local/[email protected];2", "0?Return()") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:12] ExecIf("Local/[email protected];2", "0?Set(__REC_POLICY_MODE=)") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:13] GotoIf("Local/[email protected];2", "1?exten,1") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Goto (sub-record-check,exten,1) [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:1] GotoIf("Local/[email protected];2", "1?callee") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Goto (sub-record-check,exten,8) [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:8] GosubIf("Local/[email protected];2", "0?record,1(exten,2006,5440)") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:9] Return("Local/[email protected];2", "") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:9] GotoIf("Local/[email protected];2", "1?macrodial") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Goto (macro-exten-vm,s,15) [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:15] GosubIf("Local/[email protected];2", "0?clrheader,1()") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:16] Macro("Local/[email protected];2", "dial-one,,TtrM(auto-blkvm),2006") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:1] Set("Local/[email protected];2", "DEXTEN=2006") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:2] Set("Local/[email protected];2", "DIALSTATUS_CW=") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:3] GosubIf("Local/[email protected];2", "0?screen,1()") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:4] GosubIf("Local/[email protected];2", "0?cf,1()") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:5] GotoIf("Local/[email protected];2", "1?skip1") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Goto (macro-dial-one,s,8) [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:8] GotoIf("Local/[email protected];2", "0?nodial") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:9] GotoIf("Local/[email protected];2", "0?continue") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:10] Set("Local/[email protected];2", "EXTHASCW=") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:11] GotoIf("Local/[email protected];2", "1?next1:cwinusebusy") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Goto (macro-dial-one,s,12) [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:12] GotoIf("Local/[email protected];2", "0?docfu:skip3") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Goto (macro-dial-one,s,16) [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:16] GotoIf("Local/[email protected];2", "1?next2:continue") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Goto (macro-dial-one,s,17) [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:17] GotoIf("Local/[email protected];2", "1?continue") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Goto (macro-dial-one,s,25) [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:25] GotoIf("Local/[email protected];2", "0?nodial") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:26] GosubIf("Local/[email protected];2", "1?dstring,1():dlocal,1()") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:1] Set("Local/[email protected];2", "DSTRING=") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:2] Set("Local/[email protected];2", "DEVICES=2006") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:3] ExecIf("Local/[email protected];2", "0?Return()") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:4] ExecIf("Local/[email protected];2", "0?Set(DEVICES=006)") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:5] Set("Local/[email protected];2", "LOOPCNT=1") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:6] Set("Local/[email protected];2", "ITER=1") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:7] Set("Local/[email protected];2", "THISDIAL=SIP/2006") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:8] GosubIf("Local/[email protected];2", "1?zap2dahdi,1()") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:1] ExecIf("Local/[email protected];2", "0?Return()") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:2] Set("Local/[email protected];2", "NEWDIAL=") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:3] Set("Local/[email protected];2", "LOOPCNT2=1") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:4] Set("Local/[email protected];2", "ITER2=1") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:5] Set("Local/[email protected];2", "THISPART2=SIP/2006") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:6] ExecIf("Local/[email protected];2", "0?Set(THISPART2=DAHDI/2006)") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:7] Set("Local/[email protected];2", "NEWDIAL=SIP/2006&") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:8] Set("Local/[email protected];2", "ITER2=2") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:9] GotoIf("Local/[email protected];2", "0?begin2") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:10] Set("Local/[email protected];2", "THISDIAL=SIP/2006") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:11] Return("Local/[email protected];2", "") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:9] Set("Local/[email protected];2", "DSTRING=SIP/2006&") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:10] Set("Local/[email protected];2", "ITER=2") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:11] GotoIf("Local/[email protected];2", "0?begin") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:12] Set("Local/[email protected];2", "DSTRING=SIP/2006") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:13] Return("Local/[email protected];2", "") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:27] GotoIf("Local/[email protected];2", "0?nodial") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:28] GotoIf("Local/[email protected];2", "0?skiptrace") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:29] GosubIf("Local/[email protected];2", "1?ctset,1():ctclear,1()") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:1] Set("Local/[email protected];2", "DB(CALLTRACE/2006)=5440") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:2] Return("Local/[email protected];2", "") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:30] Set("Local/[email protected];2", "D_OPTIONS=TtrM(auto-blkvm)") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:31] ExecIf("Local/[email protected];2", "0?SIPAddHeader(Alert-Info: )") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:32] ExecIf("Local/[email protected];2", "0?SIPAddHeader()") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:33] ExecIf("Local/[email protected];2", "1?Set(CHANNEL(musicclass)=ToddPiano)") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:34] GosubIf("Local/[email protected];2", "0?qwait,1()") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:35] Set("Local/[email protected];2", "__CWIGNORE=TRUE") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:36] Set("Local/[email protected];2", "__KEEPCID=TRUE") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:37] GotoIf("Local/[email protected];2", "0?usegoto,1") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:38] GotoIf("Local/[email protected];2", "0?godial") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:39] Gosub("Local/[email protected];2", "sub-presencestate-display,s,1(2006)") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:1] Goto("Local/[email protected];2", "state-available,1") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Goto (sub-presencestate-display,state-available,1) [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:1] Set("Local/[email protected];2", "PRESENCESTATE_DISPLAY=(Available)") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:2] Return("Local/[email protected];2", "") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:40] Set("Local/[email protected];2", "CONNECTEDLINE(name,i)=Idea Factory(Available)") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:41] Set("Local/[email protected];2", "CONNECTEDLINE(num)=2006") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] app_queue.c: -- Local/[email protected];1 connected line has changed. Saving it until answer for SIP/5440-00004dd0 [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:42] Set("Local/[email protected];2", "D_OPTIONS=TtrM(auto-blkvm)I") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:43] Dial("Local/[email protected];2", "SIP/2006,,TtrM(auto-blkvm)I") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] netsock2.c: == Using SIP RTP TOS bits 184 [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] netsock2.c: == Using SIP RTP CoS mark 5 [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] app_dial.c: -- Called SIP/2006 [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] app_queue.c: -- Local/[email protected];1 is ringing [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] res_musiconhold.c: -- Stopped music on hold on SIP/5440-00004dd0 [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] app_dial.c: -- Connected line update to Local/[email protected];2 prevented. [2014-05-14 15:37:33] VERBOSE[1919][C-00000c06] chan_sip.c: -- Got SIP response 486 "Busy Here" back from 10.100.5.184:5061 [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] app_dial.c: -- SIP/2006-00004dd1 is busy [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] app_dial.c: == Everyone is busy/congested at this time (1:1/0/0) [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:44] ExecIf("Local/[email protected];2", "0?MacroExit()") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:45] ExecIf("Local/[email protected];2", "0?Set(DIALSTATUS=)") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:46] GosubIf("Local/[email protected];2", "0?s-BUSY,1()") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:47] MacroExit("Local/[email protected];2", "") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:17] Set("Local/[email protected];2", "SV_DIALSTATUS=BUSY") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:18] GosubIf("Local/[email protected];2", "0?docfu,1()") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:19] GosubIf("Local/[email protected];2", "0?docfb,1()") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:20] Set("Local/[email protected];2", "DIALSTATUS=BUSY") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:21] ExecIf("Local/[email protected];2", "0?MacroExit()") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:22] GotoIf("Local/[email protected];2", "1?s-BUSY,1") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Goto (macro-exten-vm,s-BUSY,1) [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:1] GotoIf("Local/[email protected];2", "0?exit,1") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:2] PlayTones("Local/[email protected];2", "busy") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:3] Busy("Local/[email protected];2", "20") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] app_queue.c: -- Local/[email protected];1 is busy [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] app_queue.c: -- Nobody picked up in 0 ms [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] res_musiconhold.c: -- Started music on hold, class 'ToddPiano', on SIP/5440-00004dd0 [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] app_queue.c: -- LazyMembers debugging - Numbusies: 0, Numnoans2: 0, Nummems: 1 [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] app_macro.c: == Spawn extension (macro-exten-vm, s-BUSY, 3) exited non-zero on 'Local/[email protected];2' in macro 'exten-vm' [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: == Spawn extension (from-internal, 2006, 2) exited non-zero on 'Local/[email protected];2' [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [[email protected]:1] Hangup("Local/[email protected];2", "") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: == Spawn extension (from-internal, h, 1) exited non-zero on 'Local/[email protected];2' [2014-05-14 15:37:38] VERBOSE[13396][C-00000c06] res_musiconhold.c: -- Stopped music on hold on SIP/5440-00004dd0 [2014-05-14 15:37:38] VERBOSE[13396][C-00000c06] app_queue.c: -- Hold time for 9999 is 0 minute(s) 0 seconds [2014-05-14 15:37:38] VERBOSE[13396][C-00000c06] app_queue.c: -- Told SIP/5440-00004dd0 in 9999 their queue position (which was 1) [2014-05-14 15:37:38] VERBOSE[13396][C-00000c06] file.c: -- Playing 'queue-thankyou.ulaw' (language 'en')

And finally, this is with the agent phone set to DND via the FreePBX Feature Code (*76). Here again the Join Announcement does NOT play:

[2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:1] Macro("SIP/5440-00004e05", "user-callerid,") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:1] Set("SIP/5440-00004e05", "TOUCH_MONITOR=1400100519.42099") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:2] Set("SIP/5440-00004e05", "AMPUSER=5440") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:3] GotoIf("SIP/5440-00004e05", "0?report") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:4] ExecIf("SIP/5440-00004e05", "1?Set(REALCALLERIDNUM=5440)") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:5] Set("SIP/5440-00004e05", "AMPUSER=5440") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:6] GotoIf("SIP/5440-00004e05", "0?limit") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:7] Set("SIP/5440-00004e05", "AMPUSERCIDNAME=Emporium") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:8] GotoIf("SIP/5440-00004e05", "0?report") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:9] Set("SIP/5440-00004e05", "AMPUSERCID=5440") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:10] Set("SIP/5440-00004e05", "__DIAL_OPTIONS=Ttr") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:11] Set("SIP/5440-00004e05", "CALLERID(all)="Emporium" <5440>") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:12] GotoIf("SIP/5440-00004e05", "0?limit") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:13] ExecIf("SIP/5440-00004e05", "0?Set(GROUP(concurrency_limit)=5440)") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:14] ExecIf("SIP/5440-00004e05", "0?Set(CHANNEL(language)=)") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:15] GosubIf("SIP/5440-00004e05", "7?sub-ccss,s,1(from-internal,9999)") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:1] ExecIf("SIP/5440-00004e05", "0?Return()") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:2] Set("SIP/5440-00004e05", "CCSS_SETUP=TRUE") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:3] GosubIf("SIP/5440-00004e05", "0?monitor_config,1(from-internal,9999):monitor_default,1(from-internal,9999)") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:1] GotoIf("SIP/5440-00004e05", "0?is_exten") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:2] StackPop("SIP/5440-00004e05", "") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:3] Return("SIP/5440-00004e05", "FALSE") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:16] GotoIf("SIP/5440-00004e05", "0?continue") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:17] Set("SIP/5440-00004e05", "__TTL=64") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:18] GotoIf("SIP/5440-00004e05", "1?continue") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Goto (macro-user-callerid,s,29) [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:29] Set("SIP/5440-00004e05", "CALLERID(number)=5440") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:30] Set("SIP/5440-00004e05", "CALLERID(name)=Emporium") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:31] Set("SIP/5440-00004e05", "CDR(cnum)=5440") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:32] Set("SIP/5440-00004e05", "CDR(cnam)=Emporium") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:33] Set("SIP/5440-00004e05", "CHANNEL(language)=en") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:2] Answer("SIP/5440-00004e05", "") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:3] Macro("SIP/5440-00004e05", "blkvm-set,reset") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:1] ExecIf("SIP/5440-00004e05", "1?Set(__BLKVM_CHANNEL=SIP/5440-00004e05)") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:2] Set("SIP/5440-00004e05", "SHARED(BLKVM,SIP/5440-00004e05)=TRUE") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:3] Set("SIP/5440-00004e05", "GOSUB_RETVAL=TRUE") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:4] MacroExit("SIP/5440-00004e05", "") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:4] ExecIf("SIP/5440-00004e05", "1?Set(_DIAL_OPTIONS=TtrM(auto-blkvm))") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:5] Set("SIP/5440-00004e05", "__NODEST=9999") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:6] Set("SIP/5440-00004e05", "QCIDPP=") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:7] Set("SIP/5440-00004e05", "VQ_CIDPP=") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:8] ExecIf("SIP/5440-00004e05", "0?Macro(prepend-cid,)") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:9] Set("SIP/5440-00004e05", "QAINFO=") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:10] Set("SIP/5440-00004e05", "VQ_AINFO=") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:11] ExecIf("SIP/5440-00004e05", "0?Set(__ALERT_INFO=)") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:12] Set("SIP/5440-00004e05", "QJOINMSG=custom/RedFrogQueueJoin") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:13] Set("SIP/5440-00004e05", "VQ_JOINMSG=") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:14] Set("SIP/5440-00004e05", "QMOH=ToddPiano") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:15] Set("SIP/5440-00004e05", "VQ_MOH=") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:16] ExecIf("SIP/5440-00004e05", "1?Set(__MOHCLASS=ToddPiano)") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:17] ExecIf("SIP/5440-00004e05", "1?Set(CHANNEL(musicclass)=ToddPiano)") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:18] Set("SIP/5440-00004e05", "QRINGOPTS=R") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:19] Set("SIP/5440-00004e05", "QRETRY=") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:20] Set("SIP/5440-00004e05", "VQ_RETRY=") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:21] Set("SIP/5440-00004e05", "QOPTIONS=tR") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:22] Set("SIP/5440-00004e05", "VQ_OPTIONS=") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:23] Set("SIP/5440-00004e05", "QGOSUB=") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:24] Set("SIP/5440-00004e05", "VQ_GOSUB=") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:25] Set("SIP/5440-00004e05", "QAGI=") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:26] Set("SIP/5440-00004e05", "VQ_AGI=") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:27] Set("SIP/5440-00004e05", "QRULE=") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:28] Set("SIP/5440-00004e05", "VQ_RULE=") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:29] Set("SIP/5440-00004e05", "QPOSITION=") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:30] Set("SIP/5440-00004e05", "VQ_POSITION=") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:31] Gosub("SIP/5440-00004e05", "sub-record-check,s,1(q,9999,dontcare)") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:1] Set("SIP/5440-00004e05", "REC_POLICY_MODE_SAVE=") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:2] GotoIf("SIP/5440-00004e05", "1?check") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Goto (sub-record-check,s,7) [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:7] Set("SIP/5440-00004e05", "__MON_FMT=wav") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:8] GotoIf("SIP/5440-00004e05", "1?next") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Goto (sub-record-check,s,11) [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:11] ExecIf("SIP/5440-00004e05", "0?Return()") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:12] ExecIf("SIP/5440-00004e05", "1?Set(__REC_POLICY_MODE=dontcare)") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:13] GotoIf("SIP/5440-00004e05", "0?q,1") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:14] Set("SIP/5440-00004e05", "__REC_STATUS=INITIALIZED") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:15] Set("SIP/5440-00004e05", "NOW=1400100519") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:16] Set("SIP/5440-00004e05", "__DAY=14") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:17] Set("SIP/5440-00004e05", "__MONTH=05") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:18] Set("SIP/5440-00004e05", "__YEAR=2014") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:19] Set("SIP/5440-00004e05", "__TIMESTR=20140514-154839") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:20] Set("SIP/5440-00004e05", "__FROMEXTEN=5440") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:21] Set("SIP/5440-00004e05", "__CALLFILENAME=q-9999-5440-20140514-154839-1400100519.42099") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:22] Goto("SIP/5440-00004e05", "q,1") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Goto (sub-record-check,q,1) [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:1] GosubIf("SIP/5440-00004e05", "0?recq,1(q,9999,5440)") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:2] Return("SIP/5440-00004e05", "") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:32] Set("SIP/5440-00004e05", "__CWIGNORE=TRUE") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:33] ExecIf("SIP/5440-00004e05", "0?Playback(custom/RedFrogQueueJoin, )") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:34] QueueLog("SIP/5440-00004e05", "9999,1400100519.42099,NONE,DID,") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:35] Set("SIP/5440-00004e05", "QAANNOUNCE=") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:36] Set("SIP/5440-00004e05", "VQ_AANNOUNCE=") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:37] Set("SIP/5440-00004e05", "QMAXWAIT=") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:38] Set("SIP/5440-00004e05", "VQ_MAXWAIT=") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [[email protected]:39] Queue("SIP/5440-00004e05", "9999,tR,,,,,,,,") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] res_musiconhold.c: -- Started music on hold, class 'ToddPiano', on SIP/5440-00004e05 [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] app_queue.c: -- Called Local/[email protected]/n [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] app_queue.c: -- LazyMembers debugging - Numbusies: 0, Numnoans: 0, Nummems: 1 [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:1] Set("Local/[email protected];2", "QAGENT=2006") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:2] Goto("Local/[email protected];2", "9999,1") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Goto (from-queue,9999,1) [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:1] Goto("Local/[email protected];2", "from-internal,2006,1") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Goto (from-internal,2006,1) [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:1] Set("Local/[email protected];2", "__RINGTIMER=15") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:2] Macro("Local/[email protected];2", "exten-vm,novm,2006,0,0,0") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:1] Macro("Local/[email protected];2", "user-callerid,") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:1] Set("Local/[email protected];2", "TOUCH_MONITOR=1400100519.42101") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:2] Set("Local/[email protected];2", "AMPUSER=5440") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:3] GotoIf("Local/[email protected];2", "1?report") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Goto (macro-user-callerid,s,16) [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:16] GotoIf("Local/[email protected];2", "0?continue") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:17] Set("Local/[email protected];2", "__TTL=63") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:18] GotoIf("Local/[email protected];2", "1?continue") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Goto (macro-user-callerid,s,29) [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:29] Set("Local/[email protected];2", "CALLERID(number)=5440") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:30] Set("Local/[email protected];2", "CALLERID(name)=Emporium") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:31] Set("Local/[email protected];2", "CDR(cnum)=5440") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:32] Set("Local/[email protected];2", "CDR(cnam)=Emporium") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:33] Set("Local/[email protected];2", "CHANNEL(language)=en") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:2] Set("Local/[email protected];2", "RingGroupMethod=none") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:3] Set("Local/[email protected];2", "__EXTTOCALL=2006") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:4] Set("Local/[email protected];2", "__PICKUPMARK=2006") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:5] Set("Local/[email protected];2", "RT=") in new stack [2014-05-14 15:48:39] WARNING[13467][C-00000c1a] chan_sip.c: This function can only be used on SIP channels. [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:6] ExecIf("Local/[email protected];2", "0?Macro(vm,novm,DIRECTDIAL,)") in new stack [2014-05-14 15:48:39] WARNING[13467][C-00000c1a] chan_sip.c: This function can only be used on SIP channels. [2014-05-14 15:48:39] WARNING[13467][C-00000c1a] chan_sip.c: This function can only be used on SIP channels. [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:7] ExecIf("Local/[email protected];2", "0?MacroExit()") in new stack [2014-05-14 15:48:39] WARNING[13467][C-00000c1a] chan_sip.c: This function can only be used on SIP channels. [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:8] Gosub("Local/[email protected];2", "sub-record-check,s,1(exten,2006,)") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:1] Set("Local/[email protected];2", "REC_POLICY_MODE_SAVE=dontcare") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:2] GotoIf("Local/[email protected];2", "1?check") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Goto (sub-record-check,s,7) [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:7] Set("Local/[email protected];2", "__MON_FMT=wav") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:8] GotoIf("Local/[email protected];2", "1?next") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Goto (sub-record-check,s,11) [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:11] ExecIf("Local/[email protected];2", "0?Return()") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:12] ExecIf("Local/[email protected];2", "0?Set(__REC_POLICY_MODE=)") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:13] GotoIf("Local/[email protected];2", "1?exten,1") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Goto (sub-record-check,exten,1) [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:1] GotoIf("Local/[email protected];2", "1?callee") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Goto (sub-record-check,exten,8) [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:8] GosubIf("Local/[email protected];2", "0?record,1(exten,2006,5440)") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:9] Return("Local/[email protected];2", "") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:9] GotoIf("Local/[email protected];2", "1?macrodial") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Goto (macro-exten-vm,s,15) [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:15] GosubIf("Local/[email protected];2", "0?clrheader,1()") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:16] Macro("Local/[email protected];2", "dial-one,,TtrM(auto-blkvm),2006") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:1] Set("Local/[email protected];2", "DEXTEN=2006") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:2] Set("Local/[email protected];2", "DIALSTATUS_CW=") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:3] GosubIf("Local/[email protected];2", "0?screen,1()") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:4] GosubIf("Local/[email protected];2", "0?cf,1()") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:5] GotoIf("Local/[email protected];2", "0?skip1") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:6] Set("Local/[email protected];2", "DEXTEN=") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:7] Set("Local/[email protected];2", "DIALSTATUS=BUSY") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:8] GotoIf("Local/[email protected];2", "1?nodial") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Goto (macro-dial-one,s,48) [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:48] ExecIf("Local/[email protected];2", "0?Set(DIALSTATUS=NOANSWER)") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:49] NoOp("Local/[email protected];2", "Returned from dial-one with nothing to call and DIALSTATUS: BUSY") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:50] MacroExit("Local/[email protected];2", "") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:17] Set("Local/[email protected];2", "SV_DIALSTATUS=BUSY") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:18] GosubIf("Local/[email protected];2", "0?docfu,1()") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:19] GosubIf("Local/[email protected];2", "0?docfb,1()") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:20] Set("Local/[email protected];2", "DIALSTATUS=BUSY") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:21] ExecIf("Local/[email protected];2", "0?MacroExit()") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]o-exten-vm:22] GotoIf("Local/[email protected];2", "1?s-BUSY,1") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Goto (macro-exten-vm,s-BUSY,1) [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:1] GotoIf("Local/[email protected];2", "0?exit,1") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:2] PlayTones("Local/[email protected];2", "busy") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:3] Busy("Local/[email protected];2", "20") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] app_queue.c: -- Local/[email protected];1 is busy [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] app_queue.c: -- Nobody picked up in 0 ms [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] res_musiconhold.c: -- Stopped music on hold on SIP/5440-00004e05 [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] res_musiconhold.c: -- Started music on hold, class 'ToddPiano', on SIP/5440-00004e05 [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] app_queue.c: -- LazyMembers debugging - Numbusies: 0, Numnoans2: 0, Nummems: 1 [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] app_macro.c: == Spawn extension (macro-exten-vm, s-BUSY, 3) exited non-zero on 'Local/[email protected];2' in macro 'exten-vm' [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: == Spawn extension (from-internal, 2006, 2) exited non-zero on 'Local/[email protected];2' [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [[email protected]:1] Hangup("Local/[email protected];2", "") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: == Spawn extension (from-internal, h, 1) exited non-zero on 'Local/[email protected];2' [2014-05-14 15:48:44] VERBOSE[13466][C-00000c1a] res_musiconhold.c: -- Stopped music on hold on SIP/5440-00004e05 [2014-05-14 15:48:44] VERBOSE[13466][C-00000c1a] app_queue.c: -- Hold time for 9999 is 0 minute(s) 0 seconds [2014-05-14 15:48:44] VERBOSE[13466][C-00000c1a] app_queue.c: -- Told SIP/5440-00004e05 in 9999 their queue position (which was 1) [2014-05-14 15:48:44] VERBOSE[13466][C-00000c1a] file.c: -- Playing 'queue-thankyou.ulaw' (language 'en') [2014-05-14 15:48:46] VERBOSE[13466][C-00000c1a] res_musiconhold.c: -- Started music on hold, class 'ToddPiano', on SIP/5440-00004e05 [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:1] Set("Local/[email protected];2", "QAGENT=2006") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:2] Goto("Local/[email protected];2", "9999,1") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Goto (from-queue,9999,1) [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:1] Goto("Local/[email protected];2", "from-internal,2006,1") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Goto (from-internal,2006,1) [2014-05-14 15:48:46] VERBOSE[13466][C-00000c1a] app_queue.c: -- Called Local/[email protected]/n [2014-05-14 15:48:46] VERBOSE[13466][C-00000c1a] app_queue.c: -- LazyMembers debugging - Numbusies: 0, Numnoans: 0, Nummems: 1 [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:1] Set("Local/[email protected];2", "__RINGTIMER=15") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:2] Macro("Local/[email protected];2", "exten-vm,novm,2006,0,0,0") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:1] Macro("Local/[email protected];2", "user-callerid,") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:1] Set("Local/[email protected];2", "TOUCH_MONITOR=1400100526.42103") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:2] Set("Local/[email protected];2", "AMPUSER=5440") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:3] GotoIf("Local/[email protected];2", "1?report") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Goto (macro-user-callerid,s,16) [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:16] GotoIf("Local/[email protected];2", "0?continue") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:17] Set("Local/[email protected];2", "__TTL=63") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:18] GotoIf("Local/[email protected];2", "1?continue") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Goto (macro-user-callerid,s,29) [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:29] Set("Local/[email protected];2", "CALLERID(number)=5440") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:30] Set("Local/[email protected];2", "CALLERID(name)=Emporium") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:31] Set("Local/[email protected];2", "CDR(cnum)=5440") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:32] Set("Local/[email protected];2", "CDR(cnam)=Emporium") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:33] Set("Local/[email protected];2", "CHANNEL(language)=en") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:2] Set("Local/[email protected];2", "RingGroupMethod=none") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:3] Set("Local/[email protected];2", "__EXTTOCALL=2006") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:4] Set("Local/[email protected];2", "__PICKUPMARK=2006") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:5] Set("Local/[email protected];2", "RT=") in new stack [2014-05-14 15:48:46] WARNING[13468][C-00000c1a] chan_sip.c: This function can only be used on SIP channels. [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:6] ExecIf("Local/[email protected];2", "0?Macro(vm,novm,DIRECTDIAL,)") in new stack [2014-05-14 15:48:46] WARNING[13468][C-00000c1a] chan_sip.c: This function can only be used on SIP channels. [2014-05-14 15:48:46] WARNING[13468][C-00000c1a] chan_sip.c: This function can only be used on SIP channels. [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:7] ExecIf("Local/[email protected];2", "0?MacroExit()") in new stack [2014-05-14 15:48:46] WARNING[13468][C-00000c1a] chan_sip.c: This function can only be used on SIP channels. [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:8] Gosub("Local/[email protected];2", "sub-record-check,s,1(exten,2006,)") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:1] Set("Local/[email protected];2", "REC_POLICY_MODE_SAVE=dontcare") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:2] GotoIf("Local/[email protected];2", "1?check") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Goto (sub-record-check,s,7) [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]k:7] Set("Local/[email protected];2", "__MON_FMT=wav") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:8] GotoIf("Local/[email protected];2", "1?next") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Goto (sub-record-check,s,11) [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:11] ExecIf("Local/[email protected];2", "0?Return()") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:12] ExecIf("Local/[email protected];2", "0?Set(__REC_POLICY_MODE=)") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:13] GotoIf("Local/[email protected];2", "1?exten,1") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Goto (sub-record-check,exten,1) [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:1] GotoIf("Local/[email protected];2", "1?callee") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Goto (sub-record-check,exten,8) [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:8] GosubIf("Local/[email protected];2", "0?record,1(exten,2006,5440)") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:9] Return("Local/[email protected];2", "") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:9] GotoIf("Local/[email protected];2", "1?macrodial") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Goto (macro-exten-vm,s,15) [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:15] GosubIf("Local/[email protected];2", "0?clrheader,1()") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:16] Macro("Local/[email protected];2", "dial-one,,TtrM(auto-blkvm),2006") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:1] Set("Local/[email protected];2", "DEXTEN=2006") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:2] Set("Local/[email protected];2", "DIALSTATUS_CW=") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:3] GosubIf("Local/[email protected];2", "0?screen,1()") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:4] GosubIf("Local/[email protected];2", "0?cf,1()") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:5] GotoIf("Local/[email protected];2", "0?skip1") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:6] Set("Local/[email protected];2", "DEXTEN=") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:7] Set("Local/[email protected];2", "DIALSTATUS=BUSY") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:8] GotoIf("Local/[email protected];2", "1?nodial") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Goto (macro-dial-one,s,48) [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:48] ExecIf("Local/[email protected];2", "0?Set(DIALSTATUS=NOANSWER)") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:49] NoOp("Local/[email protected];2", "Returned from dial-one with nothing to call and DIALSTATUS: BUSY") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:50] MacroExit("Local/[email protected];2", "") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:17] Set("Local/[email protected];2", "SV_DIALSTATUS=BUSY") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:18] GosubIf("Local/[email protected];2", "0?docfu,1()") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:19] GosubIf("Local/[email protected];2", "0?docfb,1()") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:20] Set("Local/[email protected];2", "DIALSTATUS=BUSY") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:21] ExecIf("Local/[email protected];2", "0?MacroExit()") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:22] GotoIf("Local/[email protected];2", "1?s-BUSY,1") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Goto (macro-exten-vm,s-BUSY,1) [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:1] GotoIf("Local/[email protected];2", "0?exit,1") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:2] PlayTones("Local/[email protected];2", "busy") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [[email protected]:3] Busy("Local/[email protected];2", "20") in new stack [2014-05-14 15:48:46] VERBOSE[13466][C-00000c1a] app_queue.c: -- Local/[email protected];1 is busy [2014-05-14 15:48:46] VERBOSE[13466][C-00000c1a] app_queue.c: -- Nobody picked up in 0 ms [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] app_macro.c: == Spawn extension (macro-exten-vm, s-BUSY, 3) exited non-zero on 'Local/[email protected];2' in macro 'exten-vm' [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: == Spawn extension (from-internal, 2006, 2) exited non-zero on 'Local/[email protected];2' [2014-05-14 15:48:46] VERBOSE[13466][C-00000c1a] res_musiconhold.c: -- Stopped music on hold on SIP/5440-00004e05 [2014-05-14 15:48:46] VERBOSE[13466][C-00000c1a] res_musiconhold.c: -- Started music on hold, class 'ToddPiano', on SIP/5440-00004e05

[reinigerjm]

Just wanted to check back on this, is there any other info I can provide? Should I take this over to bug reporting?

[bksales]

why use dnd?

[SkykingOH]

Maybe I am dense would this not be expected behavior since an agent is not available. What is join on empty set to?

[reinigerjm]

We’ve just gotten used to DND because that soft key is setup on the phones out of the box, where the login/logout process is still new to our employees and prone to user error.

I’ll look into programming soft keys on the phone to automate the login/logout process. Any good resources I should start with?

[reinigerjm]

Join Empty is set to “Yes”

It is expected behavior in that since all agents are busy, the caller is placed in the Queue. What is NOT expected, is that if one of those agents is on DND, then the caller skips the informative Join Announcement and immediately starts hearing hold music and estimated hold time.