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 [9999@from-internal:1] Macro("SIP/5440-00004dae", "user-callerid,") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [s@macro-user-callerid: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 [s@macro-user-callerid:2] Set("SIP/5440-00004dae", "AMPUSER=5440") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [s@macro-user-callerid:3] GotoIf("SIP/5440-00004dae", "0?report") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [s@macro-user-callerid: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 [s@macro-user-callerid:5] Set("SIP/5440-00004dae", "AMPUSER=5440") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [s@macro-user-callerid:6] GotoIf("SIP/5440-00004dae", "0?limit") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [s@macro-user-callerid:7] Set("SIP/5440-00004dae", "AMPUSERCIDNAME=Emporium") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [s@macro-user-callerid:8] GotoIf("SIP/5440-00004dae", "0?report") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [s@macro-user-callerid:9] Set("SIP/5440-00004dae", "AMPUSERCID=5440") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [s@macro-user-callerid:10] Set("SIP/5440-00004dae", "__DIAL_OPTIONS=Ttr") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [s@macro-user-callerid: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 [s@macro-user-callerid:12] GotoIf("SIP/5440-00004dae", "0?limit") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@sub-ccss:1] ExecIf("SIP/5440-00004dae", "0?Return()") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [s@sub-ccss:2] Set("SIP/5440-00004dae", "CCSS_SETUP=TRUE") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [s@sub-ccss: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 [monitor_default@sub-ccss:1] GotoIf("SIP/5440-00004dae", "0?is_exten") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [monitor_default@sub-ccss:2] StackPop("SIP/5440-00004dae", "") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [monitor_default@sub-ccss:3] Return("SIP/5440-00004dae", "FALSE") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [s@macro-user-callerid:16] GotoIf("SIP/5440-00004dae", "0?continue") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [s@macro-user-callerid:17] Set("SIP/5440-00004dae", "__TTL=64") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [s@macro-user-callerid: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 [s@macro-user-callerid:29] Set("SIP/5440-00004dae", "CALLERID(number)=5440") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [s@macro-user-callerid:30] Set("SIP/5440-00004dae", "CALLERID(name)=Emporium") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [s@macro-user-callerid:31] Set("SIP/5440-00004dae", "CDR(cnum)=5440") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [s@macro-user-callerid:32] Set("SIP/5440-00004dae", "CDR(cnam)=Emporium") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [s@macro-user-callerid:33] Set("SIP/5440-00004dae", "CHANNEL(language)=en") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [9999@from-internal:2] Answer("SIP/5440-00004dae", "") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [9999@from-internal:3] Macro("SIP/5440-00004dae", "blkvm-set,reset") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [s@macro-blkvm-set: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 [s@macro-blkvm-set: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 [s@macro-blkvm-set:3] Set("SIP/5440-00004dae", "GOSUB_RETVAL=TRUE") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [s@macro-blkvm-set:4] MacroExit("SIP/5440-00004dae", "") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [9999@from-internal: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 [9999@from-internal:5] Set("SIP/5440-00004dae", "__NODEST=9999") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [9999@from-internal:6] Set("SIP/5440-00004dae", "QCIDPP=") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [9999@from-internal:7] Set("SIP/5440-00004dae", "VQ_CIDPP=") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [9999@from-internal: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 [9999@from-internal:9] Set("SIP/5440-00004dae", "QAINFO=") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [9999@from-internal:10] Set("SIP/5440-00004dae", "VQ_AINFO=") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [9999@from-internal: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 [9999@from-internal:12] Set("SIP/5440-00004dae", "QJOINMSG=custom/RedFrogQueueJoin") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [9999@from-internal:13] Set("SIP/5440-00004dae", "VQ_JOINMSG=") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [9999@from-internal:14] Set("SIP/5440-00004dae", "QMOH=ToddPiano") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [9999@from-internal:15] Set("SIP/5440-00004dae", "VQ_MOH=") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [9999@from-internal: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 [9999@from-internal: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 [9999@from-internal:18] Set("SIP/5440-00004dae", "QRINGOPTS=R") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [9999@from-internal:19] Set("SIP/5440-00004dae", "QRETRY=") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [9999@from-internal:20] Set("SIP/5440-00004dae", "VQ_RETRY=") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [9999@from-internal:21] Set("SIP/5440-00004dae", "QOPTIONS=tR") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [9999@from-internal:22] Set("SIP/5440-00004dae", "VQ_OPTIONS=") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [9999@from-internal:23] Set("SIP/5440-00004dae", "QGOSUB=") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [9999@from-internal:24] Set("SIP/5440-00004dae", "VQ_GOSUB=") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [9999@from-internal:25] Set("SIP/5440-00004dae", "QAGI=") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [9999@from-internal:26] Set("SIP/5440-00004dae", "VQ_AGI=") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [9999@from-internal:27] Set("SIP/5440-00004dae", "QRULE=") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [9999@from-internal:28] Set("SIP/5440-00004dae", "VQ_RULE=") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [9999@from-internal:29] Set("SIP/5440-00004dae", "QPOSITION=") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [9999@from-internal:30] Set("SIP/5440-00004dae", "VQ_POSITION=") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [9999@from-internal: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check:7] Set("SIP/5440-00004dae", "__MON_FMT=wav") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [s@sub-record-check: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 [s@sub-record-check:11] ExecIf("SIP/5440-00004dae", "0?Return()") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [s@sub-record-check: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 [s@sub-record-check:13] GotoIf("SIP/5440-00004dae", "0?q,1") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [s@sub-record-check:14] Set("SIP/5440-00004dae", "__REC_STATUS=INITIALIZED") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [s@sub-record-check:15] Set("SIP/5440-00004dae", "NOW=1400099470") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [s@sub-record-check:16] Set("SIP/5440-00004dae", "__DAY=14") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [s@sub-record-check:17] Set("SIP/5440-00004dae", "__MONTH=05") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [s@sub-record-check:18] Set("SIP/5440-00004dae", "__YEAR=2014") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [s@sub-record-check:19] Set("SIP/5440-00004dae", "__TIMESTR=20140514-153110") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [s@sub-record-check:20] Set("SIP/5440-00004dae", "__FROMEXTEN=5440") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [s@sub-record-check: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 [s@sub-record-check: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 [q@sub-record-check: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 [q@sub-record-check:2] Return("SIP/5440-00004dae", "") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [9999@from-internal:32] Set("SIP/5440-00004dae", "__CWIGNORE=TRUE") in new stack [2014-05-14 15:31:10] VERBOSE[13352][C-00000bfb] pbx.c: -- Executing [9999@from-internal: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 [9999@from-internal: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 [9999@from-internal:35] Set(“SIP/5440-00004dae”, “QAANNOUNCE=”) in new stack
[2014-05-14 15:31:42] VERBOSE[13352][C-00000bfb] pbx.c: – Executing [9999@from-internal:36] Set(“SIP/5440-00004dae”, “VQ_AANNOUNCE=”) in new stack
[2014-05-14 15:31:42] VERBOSE[13352][C-00000bfb] pbx.c: – Executing [9999@from-internal:37] Set(“SIP/5440-00004dae”, “QMAXWAIT=”) in new stack
[2014-05-14 15:31:42] VERBOSE[13352][C-00000bfb] pbx.c: – Executing [9999@from-internal:38] Set(“SIP/5440-00004dae”, “VQ_MAXWAIT=”) in new stack
[2014-05-14 15:31:42] VERBOSE[13352][C-00000bfb] pbx.c: – Executing [9999@from-internal: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 [9999@from-internal:1] Macro("SIP/5440-00004dd0", "user-callerid,") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [s@macro-user-callerid: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 [s@macro-user-callerid:2] Set("SIP/5440-00004dd0", "AMPUSER=5440") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [s@macro-user-callerid:3] GotoIf("SIP/5440-00004dd0", "0?report") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [s@macro-user-callerid: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 [s@macro-user-callerid:5] Set("SIP/5440-00004dd0", "AMPUSER=5440") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [s@macro-user-callerid:6] GotoIf("SIP/5440-00004dd0", "0?limit") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [s@macro-user-callerid:7] Set("SIP/5440-00004dd0", "AMPUSERCIDNAME=Emporium") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [s@macro-user-callerid:8] GotoIf("SIP/5440-00004dd0", "0?report") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [s@macro-user-callerid:9] Set("SIP/5440-00004dd0", "AMPUSERCID=5440") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [s@macro-user-callerid:10] Set("SIP/5440-00004dd0", "__DIAL_OPTIONS=Ttr") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [s@macro-user-callerid: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 [s@macro-user-callerid:12] GotoIf("SIP/5440-00004dd0", "0?limit") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@sub-ccss:1] ExecIf("SIP/5440-00004dd0", "0?Return()") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [s@sub-ccss:2] Set("SIP/5440-00004dd0", "CCSS_SETUP=TRUE") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [s@sub-ccss: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 [monitor_default@sub-ccss:1] GotoIf("SIP/5440-00004dd0", "0?is_exten") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [monitor_default@sub-ccss:2] StackPop("SIP/5440-00004dd0", "") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [monitor_default@sub-ccss:3] Return("SIP/5440-00004dd0", "FALSE") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [s@macro-user-callerid:16] GotoIf("SIP/5440-00004dd0", "0?continue") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [s@macro-user-callerid:17] Set("SIP/5440-00004dd0", "__TTL=64") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [s@macro-user-callerid: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 [s@macro-user-callerid:29] Set("SIP/5440-00004dd0", "CALLERID(number)=5440") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [s@macro-user-callerid:30] Set("SIP/5440-00004dd0", "CALLERID(name)=Emporium") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [s@macro-user-callerid:31] Set("SIP/5440-00004dd0", "CDR(cnum)=5440") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [s@macro-user-callerid:32] Set("SIP/5440-00004dd0", "CDR(cnam)=Emporium") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [s@macro-user-callerid:33] Set("SIP/5440-00004dd0", "CHANNEL(language)=en") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [9999@from-internal:2] Answer("SIP/5440-00004dd0", "") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [9999@from-internal:3] Macro("SIP/5440-00004dd0", "blkvm-set,reset") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [s@macro-blkvm-set: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 [s@macro-blkvm-set: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 [s@macro-blkvm-set:3] Set("SIP/5440-00004dd0", "GOSUB_RETVAL=TRUE") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [s@macro-blkvm-set:4] MacroExit("SIP/5440-00004dd0", "") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [9999@from-internal: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 [9999@from-internal:5] Set("SIP/5440-00004dd0", "__NODEST=9999") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [9999@from-internal:6] Set("SIP/5440-00004dd0", "QCIDPP=") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [9999@from-internal:7] Set("SIP/5440-00004dd0", "VQ_CIDPP=") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [9999@from-internal: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 [9999@from-internal:9] Set("SIP/5440-00004dd0", "QAINFO=") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [9999@from-internal:10] Set("SIP/5440-00004dd0", "VQ_AINFO=") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [9999@from-internal: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 [9999@from-internal:12] Set("SIP/5440-00004dd0", "QJOINMSG=custom/RedFrogQueueJoin") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [9999@from-internal:13] Set("SIP/5440-00004dd0", "VQ_JOINMSG=") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [9999@from-internal:14] Set("SIP/5440-00004dd0", "QMOH=ToddPiano") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [9999@from-internal:15] Set("SIP/5440-00004dd0", "VQ_MOH=") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [9999@from-internal: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 [9999@from-internal: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 [9999@from-internal:18] Set("SIP/5440-00004dd0", "QRINGOPTS=R") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [9999@from-internal:19] Set("SIP/5440-00004dd0", "QRETRY=") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [9999@from-internal:20] Set("SIP/5440-00004dd0", "VQ_RETRY=") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [9999@from-internal:21] Set("SIP/5440-00004dd0", "QOPTIONS=tR") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [9999@from-internal:22] Set("SIP/5440-00004dd0", "VQ_OPTIONS=") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [9999@from-internal:23] Set("SIP/5440-00004dd0", "QGOSUB=") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [9999@from-internal:24] Set("SIP/5440-00004dd0", "VQ_GOSUB=") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [9999@from-internal:25] Set("SIP/5440-00004dd0", "QAGI=") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [9999@from-internal:26] Set("SIP/5440-00004dd0", "VQ_AGI=") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [9999@from-internal:27] Set("SIP/5440-00004dd0", "QRULE=") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [9999@from-internal:28] Set("SIP/5440-00004dd0", "VQ_RULE=") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [9999@from-internal:29] Set("SIP/5440-00004dd0", "QPOSITION=") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [9999@from-internal:30] Set("SIP/5440-00004dd0", "VQ_POSITION=") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [9999@from-internal: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check:7] Set("SIP/5440-00004dd0", "__MON_FMT=wav") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [s@sub-record-check: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 [s@sub-record-check:11] ExecIf("SIP/5440-00004dd0", "0?Return()") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [s@sub-record-check: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 [s@sub-record-check:13] GotoIf("SIP/5440-00004dd0", "0?q,1") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [s@sub-record-check:14] Set("SIP/5440-00004dd0", "__REC_STATUS=INITIALIZED") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [s@sub-record-check:15] Set("SIP/5440-00004dd0", "NOW=1400099853") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [s@sub-record-check:16] Set("SIP/5440-00004dd0", "__DAY=14") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [s@sub-record-check:17] Set("SIP/5440-00004dd0", "__MONTH=05") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [s@sub-record-check:18] Set("SIP/5440-00004dd0", "__YEAR=2014") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [s@sub-record-check:19] Set("SIP/5440-00004dd0", "__TIMESTR=20140514-153733") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [s@sub-record-check:20] Set("SIP/5440-00004dd0", "__FROMEXTEN=5440") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [s@sub-record-check: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 [s@sub-record-check: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 [q@sub-record-check: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 [q@sub-record-check:2] Return("SIP/5440-00004dd0", "") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [9999@from-internal:32] Set("SIP/5440-00004dd0", "__CWIGNORE=TRUE") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [9999@from-internal: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 [9999@from-internal: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 [9999@from-internal:35] Set("SIP/5440-00004dd0", "QAANNOUNCE=") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [9999@from-internal:36] Set("SIP/5440-00004dd0", "VQ_AANNOUNCE=") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [9999@from-internal:37] Set("SIP/5440-00004dd0", "QMAXWAIT=") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [9999@from-internal:38] Set("SIP/5440-00004dd0", "VQ_MAXWAIT=") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] pbx.c: -- Executing [9999@from-internal: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 [2006@from-queue:1] Set("Local/2006@from-queue-00002b30;2", "QAGENT=2006") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] app_queue.c: -- Called Local/2006@from-queue/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 [2006@from-queue:2] Goto("Local/2006@from-queue-00002b30;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 [9999@from-queue:1] Goto("Local/2006@from-queue-00002b30;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 [2006@from-internal:1] Set("Local/2006@from-queue-00002b30;2", "__RINGTIMER=15") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [2006@from-internal:2] Macro("Local/2006@from-queue-00002b30;2", "exten-vm,novm,2006,0,0,0") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-exten-vm:1] Macro("Local/2006@from-queue-00002b30;2", "user-callerid,") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-user-callerid:1] Set("Local/2006@from-queue-00002b30;2", "TOUCH_MONITOR=1400099853.42044") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-user-callerid:2] Set("Local/2006@from-queue-00002b30;2", "AMPUSER=5440") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-user-callerid:3] GotoIf("Local/2006@from-queue-00002b30;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 [s@macro-user-callerid:16] GotoIf("Local/2006@from-queue-00002b30;2", "0?continue") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-user-callerid:17] Set("Local/2006@from-queue-00002b30;2", "__TTL=63") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-user-callerid:18] GotoIf("Local/2006@from-queue-00002b30;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 [s@macro-user-callerid:29] Set("Local/2006@from-queue-00002b30;2", "CALLERID(number)=5440") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-user-callerid:30] Set("Local/2006@from-queue-00002b30;2", "CALLERID(name)=Emporium") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-user-callerid:31] Set("Local/2006@from-queue-00002b30;2", "CDR(cnum)=5440") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-user-callerid:32] Set("Local/2006@from-queue-00002b30;2", "CDR(cnam)=Emporium") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-user-callerid:33] Set("Local/2006@from-queue-00002b30;2", "CHANNEL(language)=en") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-exten-vm:2] Set("Local/2006@from-queue-00002b30;2", "RingGroupMethod=none") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-exten-vm:3] Set("Local/2006@from-queue-00002b30;2", "__EXTTOCALL=2006") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-exten-vm:4] Set("Local/2006@from-queue-00002b30;2", "__PICKUPMARK=2006") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-exten-vm:5] Set("Local/2006@from-queue-00002b30;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 [s@macro-exten-vm:6] ExecIf("Local/2006@from-queue-00002b30;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 [s@macro-exten-vm:7] ExecIf("Local/2006@from-queue-00002b30;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 [s@macro-exten-vm:8] Gosub("Local/2006@from-queue-00002b30;2", "sub-record-check,s,1(exten,2006,)") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@sub-record-check:1] Set("Local/2006@from-queue-00002b30;2", "REC_POLICY_MODE_SAVE=dontcare") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@sub-record-check:2] GotoIf("Local/2006@from-queue-00002b30;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 [s@sub-record-check:7] Set("Local/2006@from-queue-00002b30;2", "__MON_FMT=wav") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@sub-record-check:8] GotoIf("Local/2006@from-queue-00002b30;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 [s@sub-record-check:11] ExecIf("Local/2006@from-queue-00002b30;2", "0?Return()") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@sub-record-check:12] ExecIf("Local/2006@from-queue-00002b30;2", "0?Set(__REC_POLICY_MODE=)") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@sub-record-check:13] GotoIf("Local/2006@from-queue-00002b30;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 [exten@sub-record-check:1] GotoIf("Local/2006@from-queue-00002b30;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 [exten@sub-record-check:8] GosubIf("Local/2006@from-queue-00002b30;2", "0?record,1(exten,2006,5440)") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [exten@sub-record-check:9] Return("Local/2006@from-queue-00002b30;2", "") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-exten-vm:9] GotoIf("Local/2006@from-queue-00002b30;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 [s@macro-exten-vm:15] GosubIf("Local/2006@from-queue-00002b30;2", "0?clrheader,1()") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-exten-vm:16] Macro("Local/2006@from-queue-00002b30;2", "dial-one,,TtrM(auto-blkvm),2006") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-dial-one:1] Set("Local/2006@from-queue-00002b30;2", "DEXTEN=2006") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-dial-one:2] Set("Local/2006@from-queue-00002b30;2", "DIALSTATUS_CW=") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-dial-one:3] GosubIf("Local/2006@from-queue-00002b30;2", "0?screen,1()") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-dial-one:4] GosubIf("Local/2006@from-queue-00002b30;2", "0?cf,1()") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-dial-one:5] GotoIf("Local/2006@from-queue-00002b30;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 [s@macro-dial-one:8] GotoIf("Local/2006@from-queue-00002b30;2", "0?nodial") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-dial-one:9] GotoIf("Local/2006@from-queue-00002b30;2", "0?continue") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-dial-one:10] Set("Local/2006@from-queue-00002b30;2", "EXTHASCW=") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-dial-one:11] GotoIf("Local/2006@from-queue-00002b30;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 [s@macro-dial-one:12] GotoIf("Local/2006@from-queue-00002b30;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 [s@macro-dial-one:16] GotoIf("Local/2006@from-queue-00002b30;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 [s@macro-dial-one:17] GotoIf("Local/2006@from-queue-00002b30;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 [s@macro-dial-one:25] GotoIf("Local/2006@from-queue-00002b30;2", "0?nodial") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-dial-one:26] GosubIf("Local/2006@from-queue-00002b30;2", "1?dstring,1():dlocal,1()") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [dstring@macro-dial-one:1] Set("Local/2006@from-queue-00002b30;2", "DSTRING=") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [dstring@macro-dial-one:2] Set("Local/2006@from-queue-00002b30;2", "DEVICES=2006") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [dstring@macro-dial-one:3] ExecIf("Local/2006@from-queue-00002b30;2", "0?Return()") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [dstring@macro-dial-one:4] ExecIf("Local/2006@from-queue-00002b30;2", "0?Set(DEVICES=006)") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [dstring@macro-dial-one:5] Set("Local/2006@from-queue-00002b30;2", "LOOPCNT=1") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [dstring@macro-dial-one:6] Set("Local/2006@from-queue-00002b30;2", "ITER=1") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [dstring@macro-dial-one:7] Set("Local/2006@from-queue-00002b30;2", "THISDIAL=SIP/2006") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [dstring@macro-dial-one:8] GosubIf("Local/2006@from-queue-00002b30;2", "1?zap2dahdi,1()") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [zap2dahdi@macro-dial-one:1] ExecIf("Local/2006@from-queue-00002b30;2", "0?Return()") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [zap2dahdi@macro-dial-one:2] Set("Local/2006@from-queue-00002b30;2", "NEWDIAL=") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [zap2dahdi@macro-dial-one:3] Set("Local/2006@from-queue-00002b30;2", "LOOPCNT2=1") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [zap2dahdi@macro-dial-one:4] Set("Local/2006@from-queue-00002b30;2", "ITER2=1") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [zap2dahdi@macro-dial-one:5] Set("Local/2006@from-queue-00002b30;2", "THISPART2=SIP/2006") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [zap2dahdi@macro-dial-one:6] ExecIf("Local/2006@from-queue-00002b30;2", "0?Set(THISPART2=DAHDI/2006)") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [zap2dahdi@macro-dial-one:7] Set("Local/2006@from-queue-00002b30;2", "NEWDIAL=SIP/2006&") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [zap2dahdi@macro-dial-one:8] Set("Local/2006@from-queue-00002b30;2", "ITER2=2") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [zap2dahdi@macro-dial-one:9] GotoIf("Local/2006@from-queue-00002b30;2", "0?begin2") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [zap2dahdi@macro-dial-one:10] Set("Local/2006@from-queue-00002b30;2", "THISDIAL=SIP/2006") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [zap2dahdi@macro-dial-one:11] Return("Local/2006@from-queue-00002b30;2", "") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [dstring@macro-dial-one:9] Set("Local/2006@from-queue-00002b30;2", "DSTRING=SIP/2006&") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [dstring@macro-dial-one:10] Set("Local/2006@from-queue-00002b30;2", "ITER=2") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [dstring@macro-dial-one:11] GotoIf("Local/2006@from-queue-00002b30;2", "0?begin") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [dstring@macro-dial-one:12] Set("Local/2006@from-queue-00002b30;2", "DSTRING=SIP/2006") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [dstring@macro-dial-one:13] Return("Local/2006@from-queue-00002b30;2", "") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-dial-one:27] GotoIf("Local/2006@from-queue-00002b30;2", "0?nodial") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-dial-one:28] GotoIf("Local/2006@from-queue-00002b30;2", "0?skiptrace") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-dial-one:29] GosubIf("Local/2006@from-queue-00002b30;2", "1?ctset,1():ctclear,1()") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [ctset@macro-dial-one:1] Set("Local/2006@from-queue-00002b30;2", "DB(CALLTRACE/2006)=5440") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [ctset@macro-dial-one:2] Return("Local/2006@from-queue-00002b30;2", "") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-dial-one:30] Set("Local/2006@from-queue-00002b30;2", "D_OPTIONS=TtrM(auto-blkvm)") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-dial-one:31] ExecIf("Local/2006@from-queue-00002b30;2", "0?SIPAddHeader(Alert-Info: )") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-dial-one:32] ExecIf("Local/2006@from-queue-00002b30;2", "0?SIPAddHeader()") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-dial-one:33] ExecIf("Local/2006@from-queue-00002b30;2", "1?Set(CHANNEL(musicclass)=ToddPiano)") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-dial-one:34] GosubIf("Local/2006@from-queue-00002b30;2", "0?qwait,1()") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-dial-one:35] Set("Local/2006@from-queue-00002b30;2", "__CWIGNORE=TRUE") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-dial-one:36] Set("Local/2006@from-queue-00002b30;2", "__KEEPCID=TRUE") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-dial-one:37] GotoIf("Local/2006@from-queue-00002b30;2", "0?usegoto,1") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-dial-one:38] GotoIf("Local/2006@from-queue-00002b30;2", "0?godial") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-dial-one:39] Gosub("Local/2006@from-queue-00002b30;2", "sub-presencestate-display,s,1(2006)") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@sub-presencestate-display:1] Goto("Local/2006@from-queue-00002b30;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 [state-available@sub-presencestate-display:1] Set("Local/2006@from-queue-00002b30;2", "PRESENCESTATE_DISPLAY=(Available)") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [state-available@sub-presencestate-display:2] Return("Local/2006@from-queue-00002b30;2", "") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-dial-one:40] Set("Local/2006@from-queue-00002b30;2", "CONNECTEDLINE(name,i)=Idea Factory(Available)") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-dial-one:41] Set("Local/2006@from-queue-00002b30;2", "CONNECTEDLINE(num)=2006") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] app_queue.c: -- Local/2006@from-queue-00002b30;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 [s@macro-dial-one:42] Set("Local/2006@from-queue-00002b30;2", "D_OPTIONS=TtrM(auto-blkvm)I") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-dial-one:43] Dial("Local/2006@from-queue-00002b30;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/2006@from-queue-00002b30;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/2006@from-queue-00002b30;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 [s@macro-dial-one:44] ExecIf("Local/2006@from-queue-00002b30;2", "0?MacroExit()") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-dial-one:45] ExecIf("Local/2006@from-queue-00002b30;2", "0?Set(DIALSTATUS=)") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-dial-one:46] GosubIf("Local/2006@from-queue-00002b30;2", "0?s-BUSY,1()") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-dial-one:47] MacroExit("Local/2006@from-queue-00002b30;2", "") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-exten-vm:17] Set("Local/2006@from-queue-00002b30;2", "SV_DIALSTATUS=BUSY") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-exten-vm:18] GosubIf("Local/2006@from-queue-00002b30;2", "0?docfu,1()") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-exten-vm:19] GosubIf("Local/2006@from-queue-00002b30;2", "0?docfb,1()") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-exten-vm:20] Set("Local/2006@from-queue-00002b30;2", "DIALSTATUS=BUSY") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-exten-vm:21] ExecIf("Local/2006@from-queue-00002b30;2", "0?MacroExit()") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s@macro-exten-vm:22] GotoIf("Local/2006@from-queue-00002b30;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 [s-BUSY@macro-exten-vm:1] GotoIf("Local/2006@from-queue-00002b30;2", "0?exit,1") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s-BUSY@macro-exten-vm:2] PlayTones("Local/2006@from-queue-00002b30;2", "busy") in new stack [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [s-BUSY@macro-exten-vm:3] Busy("Local/2006@from-queue-00002b30;2", "20") in new stack [2014-05-14 15:37:33] VERBOSE[13396][C-00000c06] app_queue.c: -- Local/2006@from-queue-00002b30;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/2006@from-queue-00002b30;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/2006@from-queue-00002b30;2' [2014-05-14 15:37:33] VERBOSE[13397][C-00000c06] pbx.c: -- Executing [h@from-internal:1] Hangup("Local/2006@from-queue-00002b30;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/2006@from-queue-00002b30;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 [9999@from-internal:1] Macro("SIP/5440-00004e05", "user-callerid,") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [s@macro-user-callerid: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 [s@macro-user-callerid:2] Set("SIP/5440-00004e05", "AMPUSER=5440") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [s@macro-user-callerid:3] GotoIf("SIP/5440-00004e05", "0?report") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [s@macro-user-callerid: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 [s@macro-user-callerid:5] Set("SIP/5440-00004e05", "AMPUSER=5440") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [s@macro-user-callerid:6] GotoIf("SIP/5440-00004e05", "0?limit") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [s@macro-user-callerid:7] Set("SIP/5440-00004e05", "AMPUSERCIDNAME=Emporium") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [s@macro-user-callerid:8] GotoIf("SIP/5440-00004e05", "0?report") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [s@macro-user-callerid:9] Set("SIP/5440-00004e05", "AMPUSERCID=5440") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [s@macro-user-callerid:10] Set("SIP/5440-00004e05", "__DIAL_OPTIONS=Ttr") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [s@macro-user-callerid: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 [s@macro-user-callerid:12] GotoIf("SIP/5440-00004e05", "0?limit") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@sub-ccss:1] ExecIf("SIP/5440-00004e05", "0?Return()") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [s@sub-ccss:2] Set("SIP/5440-00004e05", "CCSS_SETUP=TRUE") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [s@sub-ccss: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 [monitor_default@sub-ccss:1] GotoIf("SIP/5440-00004e05", "0?is_exten") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [monitor_default@sub-ccss:2] StackPop("SIP/5440-00004e05", "") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [monitor_default@sub-ccss:3] Return("SIP/5440-00004e05", "FALSE") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [s@macro-user-callerid:16] GotoIf("SIP/5440-00004e05", "0?continue") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [s@macro-user-callerid:17] Set("SIP/5440-00004e05", "__TTL=64") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [s@macro-user-callerid: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 [s@macro-user-callerid:29] Set("SIP/5440-00004e05", "CALLERID(number)=5440") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [s@macro-user-callerid:30] Set("SIP/5440-00004e05", "CALLERID(name)=Emporium") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [s@macro-user-callerid:31] Set("SIP/5440-00004e05", "CDR(cnum)=5440") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [s@macro-user-callerid:32] Set("SIP/5440-00004e05", "CDR(cnam)=Emporium") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [s@macro-user-callerid:33] Set("SIP/5440-00004e05", "CHANNEL(language)=en") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [9999@from-internal:2] Answer("SIP/5440-00004e05", "") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [9999@from-internal:3] Macro("SIP/5440-00004e05", "blkvm-set,reset") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [s@macro-blkvm-set: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 [s@macro-blkvm-set: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 [s@macro-blkvm-set:3] Set("SIP/5440-00004e05", "GOSUB_RETVAL=TRUE") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [s@macro-blkvm-set:4] MacroExit("SIP/5440-00004e05", "") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [9999@from-internal: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 [9999@from-internal:5] Set("SIP/5440-00004e05", "__NODEST=9999") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [9999@from-internal:6] Set("SIP/5440-00004e05", "QCIDPP=") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [9999@from-internal:7] Set("SIP/5440-00004e05", "VQ_CIDPP=") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [9999@from-internal: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 [9999@from-internal:9] Set("SIP/5440-00004e05", "QAINFO=") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [9999@from-internal:10] Set("SIP/5440-00004e05", "VQ_AINFO=") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [9999@from-internal: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 [9999@from-internal:12] Set("SIP/5440-00004e05", "QJOINMSG=custom/RedFrogQueueJoin") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [9999@from-internal:13] Set("SIP/5440-00004e05", "VQ_JOINMSG=") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [9999@from-internal:14] Set("SIP/5440-00004e05", "QMOH=ToddPiano") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [9999@from-internal:15] Set("SIP/5440-00004e05", "VQ_MOH=") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [9999@from-internal: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 [9999@from-internal: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 [9999@from-internal:18] Set("SIP/5440-00004e05", "QRINGOPTS=R") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [9999@from-internal:19] Set("SIP/5440-00004e05", "QRETRY=") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [9999@from-internal:20] Set("SIP/5440-00004e05", "VQ_RETRY=") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [9999@from-internal:21] Set("SIP/5440-00004e05", "QOPTIONS=tR") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [9999@from-internal:22] Set("SIP/5440-00004e05", "VQ_OPTIONS=") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [9999@from-internal:23] Set("SIP/5440-00004e05", "QGOSUB=") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [9999@from-internal:24] Set("SIP/5440-00004e05", "VQ_GOSUB=") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [9999@from-internal:25] Set("SIP/5440-00004e05", "QAGI=") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [9999@from-internal:26] Set("SIP/5440-00004e05", "VQ_AGI=") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [9999@from-internal:27] Set("SIP/5440-00004e05", "QRULE=") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [9999@from-internal:28] Set("SIP/5440-00004e05", "VQ_RULE=") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [9999@from-internal:29] Set("SIP/5440-00004e05", "QPOSITION=") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [9999@from-internal:30] Set("SIP/5440-00004e05", "VQ_POSITION=") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [9999@from-internal: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check:7] Set("SIP/5440-00004e05", "__MON_FMT=wav") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [s@sub-record-check: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 [s@sub-record-check:11] ExecIf("SIP/5440-00004e05", "0?Return()") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [s@sub-record-check: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 [s@sub-record-check:13] GotoIf("SIP/5440-00004e05", "0?q,1") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [s@sub-record-check:14] Set("SIP/5440-00004e05", "__REC_STATUS=INITIALIZED") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [s@sub-record-check:15] Set("SIP/5440-00004e05", "NOW=1400100519") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [s@sub-record-check:16] Set("SIP/5440-00004e05", "__DAY=14") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [s@sub-record-check:17] Set("SIP/5440-00004e05", "__MONTH=05") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [s@sub-record-check:18] Set("SIP/5440-00004e05", "__YEAR=2014") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [s@sub-record-check:19] Set("SIP/5440-00004e05", "__TIMESTR=20140514-154839") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [s@sub-record-check:20] Set("SIP/5440-00004e05", "__FROMEXTEN=5440") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [s@sub-record-check: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 [s@sub-record-check: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 [q@sub-record-check: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 [q@sub-record-check:2] Return("SIP/5440-00004e05", "") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [9999@from-internal:32] Set("SIP/5440-00004e05", "__CWIGNORE=TRUE") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [9999@from-internal: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 [9999@from-internal: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 [9999@from-internal:35] Set("SIP/5440-00004e05", "QAANNOUNCE=") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [9999@from-internal:36] Set("SIP/5440-00004e05", "VQ_AANNOUNCE=") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [9999@from-internal:37] Set("SIP/5440-00004e05", "QMAXWAIT=") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [9999@from-internal:38] Set("SIP/5440-00004e05", "VQ_MAXWAIT=") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] pbx.c: -- Executing [9999@from-internal: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/2006@from-queue/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 [2006@from-queue:1] Set("Local/2006@from-queue-00002b32;2", "QAGENT=2006") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [2006@from-queue:2] Goto("Local/2006@from-queue-00002b32;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 [9999@from-queue:1] Goto("Local/2006@from-queue-00002b32;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 [2006@from-internal:1] Set("Local/2006@from-queue-00002b32;2", "__RINGTIMER=15") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [2006@from-internal:2] Macro("Local/2006@from-queue-00002b32;2", "exten-vm,novm,2006,0,0,0") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [s@macro-exten-vm:1] Macro("Local/2006@from-queue-00002b32;2", "user-callerid,") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [s@macro-user-callerid:1] Set("Local/2006@from-queue-00002b32;2", "TOUCH_MONITOR=1400100519.42101") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [s@macro-user-callerid:2] Set("Local/2006@from-queue-00002b32;2", "AMPUSER=5440") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [s@macro-user-callerid:3] GotoIf("Local/2006@from-queue-00002b32;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 [s@macro-user-callerid:16] GotoIf("Local/2006@from-queue-00002b32;2", "0?continue") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [s@macro-user-callerid:17] Set("Local/2006@from-queue-00002b32;2", "__TTL=63") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [s@macro-user-callerid:18] GotoIf("Local/2006@from-queue-00002b32;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 [s@macro-user-callerid:29] Set("Local/2006@from-queue-00002b32;2", "CALLERID(number)=5440") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [s@macro-user-callerid:30] Set("Local/2006@from-queue-00002b32;2", "CALLERID(name)=Emporium") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [s@macro-user-callerid:31] Set("Local/2006@from-queue-00002b32;2", "CDR(cnum)=5440") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [s@macro-user-callerid:32] Set("Local/2006@from-queue-00002b32;2", "CDR(cnam)=Emporium") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [s@macro-user-callerid:33] Set("Local/2006@from-queue-00002b32;2", "CHANNEL(language)=en") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [s@macro-exten-vm:2] Set("Local/2006@from-queue-00002b32;2", "RingGroupMethod=none") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [s@macro-exten-vm:3] Set("Local/2006@from-queue-00002b32;2", "__EXTTOCALL=2006") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [s@macro-exten-vm:4] Set("Local/2006@from-queue-00002b32;2", "__PICKUPMARK=2006") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [s@macro-exten-vm:5] Set("Local/2006@from-queue-00002b32;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 [s@macro-exten-vm:6] ExecIf("Local/2006@from-queue-00002b32;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 [s@macro-exten-vm:7] ExecIf("Local/2006@from-queue-00002b32;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 [s@macro-exten-vm:8] Gosub("Local/2006@from-queue-00002b32;2", "sub-record-check,s,1(exten,2006,)") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [s@sub-record-check:1] Set("Local/2006@from-queue-00002b32;2", "REC_POLICY_MODE_SAVE=dontcare") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [s@sub-record-check:2] GotoIf("Local/2006@from-queue-00002b32;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 [s@sub-record-check:7] Set("Local/2006@from-queue-00002b32;2", "__MON_FMT=wav") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [s@sub-record-check:8] GotoIf("Local/2006@from-queue-00002b32;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 [s@sub-record-check:11] ExecIf("Local/2006@from-queue-00002b32;2", "0?Return()") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [s@sub-record-check:12] ExecIf("Local/2006@from-queue-00002b32;2", "0?Set(__REC_POLICY_MODE=)") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [s@sub-record-check:13] GotoIf("Local/2006@from-queue-00002b32;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 [exten@sub-record-check:1] GotoIf("Local/2006@from-queue-00002b32;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 [exten@sub-record-check:8] GosubIf("Local/2006@from-queue-00002b32;2", "0?record,1(exten,2006,5440)") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [exten@sub-record-check:9] Return("Local/2006@from-queue-00002b32;2", "") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [s@macro-exten-vm:9] GotoIf("Local/2006@from-queue-00002b32;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 [s@macro-exten-vm:15] GosubIf("Local/2006@from-queue-00002b32;2", "0?clrheader,1()") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [s@macro-exten-vm:16] Macro("Local/2006@from-queue-00002b32;2", "dial-one,,TtrM(auto-blkvm),2006") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [s@macro-dial-one:1] Set("Local/2006@from-queue-00002b32;2", "DEXTEN=2006") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [s@macro-dial-one:2] Set("Local/2006@from-queue-00002b32;2", "DIALSTATUS_CW=") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [s@macro-dial-one:3] GosubIf("Local/2006@from-queue-00002b32;2", "0?screen,1()") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [s@macro-dial-one:4] GosubIf("Local/2006@from-queue-00002b32;2", "0?cf,1()") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [s@macro-dial-one:5] GotoIf("Local/2006@from-queue-00002b32;2", "0?skip1") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [s@macro-dial-one:6] Set("Local/2006@from-queue-00002b32;2", "DEXTEN=") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [s@macro-dial-one:7] Set("Local/2006@from-queue-00002b32;2", "DIALSTATUS=BUSY") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [s@macro-dial-one:8] GotoIf("Local/2006@from-queue-00002b32;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 [s@macro-dial-one:48] ExecIf("Local/2006@from-queue-00002b32;2", "0?Set(DIALSTATUS=NOANSWER)") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [s@macro-dial-one:49] NoOp("Local/2006@from-queue-00002b32;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 [s@macro-dial-one:50] MacroExit("Local/2006@from-queue-00002b32;2", "") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [s@macro-exten-vm:17] Set("Local/2006@from-queue-00002b32;2", "SV_DIALSTATUS=BUSY") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [s@macro-exten-vm:18] GosubIf("Local/2006@from-queue-00002b32;2", "0?docfu,1()") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [s@macro-exten-vm:19] GosubIf("Local/2006@from-queue-00002b32;2", "0?docfb,1()") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [s@macro-exten-vm:20] Set("Local/2006@from-queue-00002b32;2", "DIALSTATUS=BUSY") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [s@macro-exten-vm:21] ExecIf("Local/2006@from-queue-00002b32;2", "0?MacroExit()") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [s@macro-exten-vm:22] GotoIf("Local/2006@from-queue-00002b32;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 [s-BUSY@macro-exten-vm:1] GotoIf("Local/2006@from-queue-00002b32;2", "0?exit,1") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [s-BUSY@macro-exten-vm:2] PlayTones("Local/2006@from-queue-00002b32;2", "busy") in new stack [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [s-BUSY@macro-exten-vm:3] Busy("Local/2006@from-queue-00002b32;2", "20") in new stack [2014-05-14 15:48:39] VERBOSE[13466][C-00000c1a] app_queue.c: -- Local/2006@from-queue-00002b32;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/2006@from-queue-00002b32;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/2006@from-queue-00002b32;2' [2014-05-14 15:48:39] VERBOSE[13467][C-00000c1a] pbx.c: -- Executing [h@from-internal:1] Hangup("Local/2006@from-queue-00002b32;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/2006@from-queue-00002b32;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 [2006@from-queue:1] Set("Local/2006@from-queue-00002b33;2", "QAGENT=2006") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [2006@from-queue:2] Goto("Local/2006@from-queue-00002b33;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 [9999@from-queue:1] Goto("Local/2006@from-queue-00002b33;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/2006@from-queue/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 [2006@from-internal:1] Set("Local/2006@from-queue-00002b33;2", "__RINGTIMER=15") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [2006@from-internal:2] Macro("Local/2006@from-queue-00002b33;2", "exten-vm,novm,2006,0,0,0") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [s@macro-exten-vm:1] Macro("Local/2006@from-queue-00002b33;2", "user-callerid,") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [s@macro-user-callerid:1] Set("Local/2006@from-queue-00002b33;2", "TOUCH_MONITOR=1400100526.42103") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [s@macro-user-callerid:2] Set("Local/2006@from-queue-00002b33;2", "AMPUSER=5440") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [s@macro-user-callerid:3] GotoIf("Local/2006@from-queue-00002b33;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 [s@macro-user-callerid:16] GotoIf("Local/2006@from-queue-00002b33;2", "0?continue") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [s@macro-user-callerid:17] Set("Local/2006@from-queue-00002b33;2", "__TTL=63") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [s@macro-user-callerid:18] GotoIf("Local/2006@from-queue-00002b33;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 [s@macro-user-callerid:29] Set("Local/2006@from-queue-00002b33;2", "CALLERID(number)=5440") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [s@macro-user-callerid:30] Set("Local/2006@from-queue-00002b33;2", "CALLERID(name)=Emporium") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [s@macro-user-callerid:31] Set("Local/2006@from-queue-00002b33;2", "CDR(cnum)=5440") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [s@macro-user-callerid:32] Set("Local/2006@from-queue-00002b33;2", "CDR(cnam)=Emporium") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [s@macro-user-callerid:33] Set("Local/2006@from-queue-00002b33;2", "CHANNEL(language)=en") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [s@macro-exten-vm:2] Set("Local/2006@from-queue-00002b33;2", "RingGroupMethod=none") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [s@macro-exten-vm:3] Set("Local/2006@from-queue-00002b33;2", "__EXTTOCALL=2006") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [s@macro-exten-vm:4] Set("Local/2006@from-queue-00002b33;2", "__PICKUPMARK=2006") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [s@macro-exten-vm:5] Set("Local/2006@from-queue-00002b33;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 [s@macro-exten-vm:6] ExecIf("Local/2006@from-queue-00002b33;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 [s@macro-exten-vm:7] ExecIf("Local/2006@from-queue-00002b33;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 [s@macro-exten-vm:8] Gosub("Local/2006@from-queue-00002b33;2", "sub-record-check,s,1(exten,2006,)") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [s@sub-record-check:1] Set("Local/2006@from-queue-00002b33;2", "REC_POLICY_MODE_SAVE=dontcare") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [s@sub-record-check:2] GotoIf("Local/2006@from-queue-00002b33;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 [s@sub-record-check:7] Set("Local/2006@from-queue-00002b33;2", "__MON_FMT=wav") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [s@sub-record-check:8] GotoIf("Local/2006@from-queue-00002b33;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 [s@sub-record-check:11] ExecIf("Local/2006@from-queue-00002b33;2", "0?Return()") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [s@sub-record-check:12] ExecIf("Local/2006@from-queue-00002b33;2", "0?Set(__REC_POLICY_MODE=)") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [s@sub-record-check:13] GotoIf("Local/2006@from-queue-00002b33;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 [exten@sub-record-check:1] GotoIf("Local/2006@from-queue-00002b33;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 [exten@sub-record-check:8] GosubIf("Local/2006@from-queue-00002b33;2", "0?record,1(exten,2006,5440)") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [exten@sub-record-check:9] Return("Local/2006@from-queue-00002b33;2", "") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [s@macro-exten-vm:9] GotoIf("Local/2006@from-queue-00002b33;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 [s@macro-exten-vm:15] GosubIf("Local/2006@from-queue-00002b33;2", "0?clrheader,1()") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [s@macro-exten-vm:16] Macro("Local/2006@from-queue-00002b33;2", "dial-one,,TtrM(auto-blkvm),2006") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [s@macro-dial-one:1] Set("Local/2006@from-queue-00002b33;2", "DEXTEN=2006") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [s@macro-dial-one:2] Set("Local/2006@from-queue-00002b33;2", "DIALSTATUS_CW=") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [s@macro-dial-one:3] GosubIf("Local/2006@from-queue-00002b33;2", "0?screen,1()") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [s@macro-dial-one:4] GosubIf("Local/2006@from-queue-00002b33;2", "0?cf,1()") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [s@macro-dial-one:5] GotoIf("Local/2006@from-queue-00002b33;2", "0?skip1") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [s@macro-dial-one:6] Set("Local/2006@from-queue-00002b33;2", "DEXTEN=") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [s@macro-dial-one:7] Set("Local/2006@from-queue-00002b33;2", "DIALSTATUS=BUSY") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [s@macro-dial-one:8] GotoIf("Local/2006@from-queue-00002b33;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 [s@macro-dial-one:48] ExecIf("Local/2006@from-queue-00002b33;2", "0?Set(DIALSTATUS=NOANSWER)") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [s@macro-dial-one:49] NoOp("Local/2006@from-queue-00002b33;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 [s@macro-dial-one:50] MacroExit("Local/2006@from-queue-00002b33;2", "") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [s@macro-exten-vm:17] Set("Local/2006@from-queue-00002b33;2", "SV_DIALSTATUS=BUSY") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [s@macro-exten-vm:18] GosubIf("Local/2006@from-queue-00002b33;2", "0?docfu,1()") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [s@macro-exten-vm:19] GosubIf("Local/2006@from-queue-00002b33;2", "0?docfb,1()") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [s@macro-exten-vm:20] Set("Local/2006@from-queue-00002b33;2", "DIALSTATUS=BUSY") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [s@macro-exten-vm:21] ExecIf("Local/2006@from-queue-00002b33;2", "0?MacroExit()") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [s@macro-exten-vm:22] GotoIf("Local/2006@from-queue-00002b33;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 [s-BUSY@macro-exten-vm:1] GotoIf("Local/2006@from-queue-00002b33;2", "0?exit,1") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [s-BUSY@macro-exten-vm:2] PlayTones("Local/2006@from-queue-00002b33;2", "busy") in new stack [2014-05-14 15:48:46] VERBOSE[13468][C-00000c1a] pbx.c: -- Executing [s-BUSY@macro-exten-vm:3] Busy("Local/2006@from-queue-00002b33;2", "20") in new stack [2014-05-14 15:48:46] VERBOSE[13466][C-00000c1a] app_queue.c: -- Local/2006@from-queue-00002b33;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/2006@from-queue-00002b33;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/2006@from-queue-00002b33;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.