[Oct  7 14:58:26] VERBOSE[3129] logger.c:     -- Executing [6107342734@from-pstn:1] Set("SIP/ewrinf-b702dfc8", "__FROM_DID=6107342734") in new stack
[Oct  7 14:58:26] VERBOSE[3129] logger.c:     -- Executing [6107342734@from-pstn:2] Set("SIP/ewrinf-b702dfc8", "CDR(accountcode)=6107342734") in new stack
[Oct  7 14:58:26] VERBOSE[3129] logger.c:     -- Executing [6107342734@from-pstn:3] Set("SIP/ewrinf-b702dfc8", "__CALLINGCHANNEL=SIP/ewrinf-b702dfc8") in new stack
[Oct  7 14:58:26] VERBOSE[3129] logger.c:     -- Executing [6107342734@from-pstn:4] SetCallerPres("SIP/ewrinf-b702dfc8", "allowed_not_screened") in new stack
[Oct  7 14:58:26] VERBOSE[3129] logger.c:     -- Executing [6107342734@from-pstn:5] Goto("SIP/ewrinf-b702dfc8", "app-queueprio|1|1") in new stack
[Oct  7 14:58:26] VERBOSE[3129] logger.c:     -- Goto (app-queueprio,1,1)
[Oct  7 14:58:26] VERBOSE[3129] logger.c:     -- Executing [1@app-queueprio:1] NoOp("SIP/ewrinf-b702dfc8", "Changing Channel to queueprio: 7 (Check In)") in new stack
[Oct  7 14:58:26] VERBOSE[3129] logger.c:     -- Executing [1@app-queueprio:2] Set("SIP/ewrinf-b702dfc8", "_QUEUE_PRIO=7") in new stack
[Oct  7 14:58:26] VERBOSE[3129] logger.c:     -- Executing [1@app-queueprio:3] Goto("SIP/ewrinf-b702dfc8", "ext-queues|600|1") in new stack
[Oct  7 14:58:26] VERBOSE[3129] logger.c:     -- Goto (ext-queues,600,1)
[Oct  7 14:58:26] VERBOSE[3129] logger.c:     -- Executing [600@ext-queues:1] Macro("SIP/ewrinf-b702dfc8", "user-callerid|") in new stack
[Oct  7 14:58:26] VERBOSE[3129] logger.c:     -- Executing [s@macro-user-callerid:1] Set("SIP/ewrinf-b702dfc8", "AMPUSER=+16107837765") in new stack
[Oct  7 14:58:26] DEBUG[3129] app_macro.c: Executed application: Set
[Oct  7 14:58:26] VERBOSE[3129] logger.c:     -- Executing [s@macro-user-callerid:2] GotoIf("SIP/ewrinf-b702dfc8", "0?report") in new stack
[Oct  7 14:58:26] DEBUG[3129] app_macro.c: Executed application: GotoIf
[Oct  7 14:58:26] VERBOSE[3129] logger.c:     -- Executing [s@macro-user-callerid:3] ExecIf("SIP/ewrinf-b702dfc8", "1|Set|REALCALLERIDNUM=+16107837765") in new stack
[Oct  7 14:58:26] DEBUG[3129] app_macro.c: Executed application: ExecIf
[Oct  7 14:58:26] DEBUG[3129] func_db.c: DB: DEVICE/+16107837765/user not found in database.
[Oct  7 14:58:26] VERBOSE[3129] logger.c:     -- Executing [s@macro-user-callerid:4] Set("SIP/ewrinf-b702dfc8", "AMPUSER=") in new stack
[Oct  7 14:58:26] DEBUG[3129] app_macro.c: Executed application: Set
[Oct  7 14:58:26] DEBUG[3129] func_db.c: DB: AMPUSER//cidname not found in database.
[Oct  7 14:58:26] VERBOSE[3129] logger.c:     -- Executing [s@macro-user-callerid:5] Set("SIP/ewrinf-b702dfc8", "AMPUSERCIDNAME=") in new stack
[Oct  7 14:58:26] DEBUG[3129] app_macro.c: Executed application: Set
[Oct  7 14:58:26] VERBOSE[3129] logger.c:     -- Executing [s@macro-user-callerid:6] GotoIf("SIP/ewrinf-b702dfc8", "1?report") in new stack
[Oct  7 14:58:26] VERBOSE[3129] logger.c:     -- Goto (macro-user-callerid,s,10)
[Oct  7 14:58:26] DEBUG[3129] app_macro.c: Executed application: GotoIf
[Oct  7 14:58:26] VERBOSE[3129] logger.c:     -- Executing [s@macro-user-callerid:10] GotoIf("SIP/ewrinf-b702dfc8", "0?continue") in new stack
[Oct  7 14:58:26] DEBUG[3129] app_macro.c: Executed application: GotoIf
[Oct  7 14:58:26] VERBOSE[3129] logger.c:     -- Executing [s@macro-user-callerid:11] Set("SIP/ewrinf-b702dfc8", "__TTL=64") in new stack
[Oct  7 14:58:26] DEBUG[3129] app_macro.c: Executed application: Set
[Oct  7 14:58:26] VERBOSE[3129] logger.c:     -- Executing [s@macro-user-callerid:12] GotoIf("SIP/ewrinf-b702dfc8", "1?continue") in new stack
[Oct  7 14:58:26] VERBOSE[3129] logger.c:     -- Goto (macro-user-callerid,s,19)
[Oct  7 14:58:26] DEBUG[3129] app_macro.c: Executed application: GotoIf
[Oct  7 14:58:26] VERBOSE[3129] logger.c:     -- Executing [s@macro-user-callerid:19] NoOp("SIP/ewrinf-b702dfc8", "Using CallerID "TAS MGT CO     " <+16107837765>") in new stack
[Oct  7 14:58:26] DEBUG[3129] app_macro.c: Executed application: Noop
[Oct  7 14:58:26] VERBOSE[3129] logger.c:     -- Executing [600@ext-queues:2] Answer("SIP/ewrinf-b702dfc8", "") in new stack
[Oct  7 14:58:26] VERBOSE[3129] logger.c:     -- Executing [600@ext-queues:3] Set("SIP/ewrinf-b702dfc8", "__BLKVM_OVERRIDE=BLKVM/600/SIP/ewrinf-b702dfc8") in new stack
[Oct  7 14:58:26] VERBOSE[3129] logger.c:     -- Executing [600@ext-queues:4] Set("SIP/ewrinf-b702dfc8", "__BLKVM_BASE=600") in new stack
[Oct  7 14:58:26] VERBOSE[3129] logger.c:     -- Executing [600@ext-queues:5] Set("SIP/ewrinf-b702dfc8", "DB(BLKVM/600/SIP/ewrinf-b702dfc8)=TRUE") in new stack
[Oct  7 14:58:26] VERBOSE[3129] logger.c:     -- Executing [600@ext-queues:6] ExecIf("SIP/ewrinf-b702dfc8", "1|Set|_DIAL_OPTIONS=trM(auto-blkvm)") in new stack
[Oct  7 14:58:26] VERBOSE[3129] logger.c:     -- Executing [600@ext-queues:7] Set("SIP/ewrinf-b702dfc8", "__NODEST=600") in new stack
[Oct  7 14:58:26] VERBOSE[3129] logger.c:     -- Executing [600@ext-queues:8] Set("SIP/ewrinf-b702dfc8", "__ALERT_INFO=AA") in new stack
[Oct  7 14:58:26] VERBOSE[3129] logger.c:     -- Executing [600@ext-queues:9] Set("SIP/ewrinf-b702dfc8", "MONITOR_FILENAME=/var/spool/asterisk/monitor/q600-20091007-145826-1254941906.100538") in new stack
[Oct  7 14:58:26] VERBOSE[3129] logger.c:     -- Executing [600@ext-queues:10] Set("SIP/ewrinf-b702dfc8", "__MOHCLASS=default") in new stack
[Oct  7 14:58:26] VERBOSE[3129] logger.c:     -- Executing [600@ext-queues:11] Set("SIP/ewrinf-b702dfc8", "__CWIGNORE=TRUE") in new stack
[Oct  7 14:58:26] VERBOSE[3129] logger.c:     -- Executing [600@ext-queues:12] Queue("SIP/ewrinf-b702dfc8", "600|tr||custom/infra_announce|20") in new stack
[Oct  7 14:58:27] VERBOSE[3129] logger.c:     -- SIP/115-0a30fe50 is busy
[Oct  7 14:58:27] VERBOSE[3129] logger.c:     -- Nobody picked up in 1000 ms
[Oct  7 14:58:27] VERBOSE[3129] logger.c:     -- SIP/113-0a28aa40 is busy
[Oct  7 14:58:27] VERBOSE[3129] logger.c:     -- Nobody picked up in 1000 ms
[Oct  7 14:58:27] VERBOSE[3129] logger.c:     -- SIP/506-0a30fe50 is circuit-busy
[Oct  7 14:58:27] VERBOSE[3129] logger.c:     -- Nobody picked up in 1000 ms
[Oct  7 14:58:27] VERBOSE[3129] logger.c:     -- SIP/107-0a28aa40 is ringing
[Oct  7 14:58:35] VERBOSE[3129] logger.c:     -- SIP/107-0a28aa40 answered SIP/ewrinf-b702dfc8
[Oct  7 14:58:35] VERBOSE[3129] logger.c:     -- <SIP/107-0a28aa40> Playing 'custom/infra_announce' (language 'en')
[Oct  7 14:58:38] NOTICE[3129] app_queue.c: Caller was about to talk to agent on SIP/107-0a28aa40 but the caller hungup.
[Oct  7 14:58:38] VERBOSE[3129] logger.c:   == Spawn extension (from-internal, 2014, 0) exited non-zero on 'SIP/ewrinf-b702dfc8'
[Oct  7 14:58:38] VERBOSE[3129] logger.c:     -- Executing [2014@from-internal:1] NoOp("SIP/ewrinf-b702dfc8", " -- Attempting to call SIP 2014 --") in new stack
[Oct  7 14:58:38] VERBOSE[3129] logger.c:     -- Executing [2014@from-internal:2] Dial("SIP/ewrinf-b702dfc8", "SIP/2014|999|r") in new stack
[Oct  7 14:58:38] VERBOSE[3129] logger.c:     -- Called 2014
[Oct  7 14:58:38] VERBOSE[3129] logger.c:   == Spawn extension (from-internal, 2014, 2) exited non-zero on 'SIP/ewrinf-b702dfc8'
[Oct  7 14:58:38] VERBOSE[3129] logger.c:     -- Executing [h@from-internal:1] Macro("SIP/ewrinf-b702dfc8", "hangupcall") in new stack
[Oct  7 14:58:38] VERBOSE[3129] logger.c:     -- Executing [s@macro-hangupcall:1] ResetCDR("SIP/ewrinf-b702dfc8", "vw") in new stack
[Oct  7 14:58:38] DEBUG[3129] app_macro.c: Executed application: ResetCDR
[Oct  7 14:58:38] VERBOSE[3129] logger.c:     -- Executing [s@macro-hangupcall:2] NoCDR("SIP/ewrinf-b702dfc8", "") in new stack
[Oct  7 14:58:38] DEBUG[3129] app_macro.c: Executed application: NoCDR
[Oct  7 14:58:38] VERBOSE[3129] logger.c:     -- Executing [s@macro-hangupcall:3] GotoIf("SIP/ewrinf-b702dfc8", "1?skiprg") in new stack
[Oct  7 14:58:38] VERBOSE[3129] logger.c:     -- Goto (macro-hangupcall,s,6)
[Oct  7 14:58:38] DEBUG[3129] app_macro.c: Executed application: GotoIf
[Oct  7 14:58:38] VERBOSE[3129] logger.c:     -- Executing [s@macro-hangupcall:6] GotoIf("SIP/ewrinf-b702dfc8", "0?skipblkvm") in new stack
[Oct  7 14:58:38] DEBUG[3129] app_macro.c: Executed application: GotoIf
[Oct  7 14:58:38] VERBOSE[3129] logger.c:     -- Executing [s@macro-hangupcall:7] NoOp("SIP/ewrinf-b702dfc8", "Cleaning Up Block VM Flag: BLKVM/600/SIP/ewrinf-b702dfc8") in new stack
[Oct  7 14:58:38] DEBUG[3129] app_macro.c: Executed application: Noop
[Oct  7 14:58:38] VERBOSE[3129] logger.c:     -- Executing [s@macro-hangupcall:8] DBdel("SIP/ewrinf-b702dfc8", "BLKVM/600/SIP/ewrinf-b702dfc8") in new stack
[Oct  7 14:58:38] VERBOSE[3129] logger.c:     -- DBdel: family=BLKVM, key=600/SIP/ewrinf-b702dfc8
[Oct  7 14:58:38] DEBUG[3129] app_macro.c: Executed application: DBDel
[Oct  7 14:58:38] VERBOSE[3129] logger.c:     -- Executing [s@macro-hangupcall:9] GotoIf("SIP/ewrinf-b702dfc8", "1?theend") in new stack
[Oct  7 14:58:38] VERBOSE[3129] logger.c:     -- Goto (macro-hangupcall,s,11)
[Oct  7 14:58:38] DEBUG[3129] app_macro.c: Executed application: GotoIf
[Oct  7 14:58:38] VERBOSE[3129] logger.c:     -- Executing [s@macro-hangupcall:11] Hangup("SIP/ewrinf-b702dfc8", "") in new stack
[Oct  7 14:58:38] VERBOSE[3129] logger.c:   == Spawn extension (macro-hangupcall, s, 11) exited non-zero on 'SIP/ewrinf-b702dfc8' in macro 'hangupcall'
[Oct  7 14:58:38] VERBOSE[3129] logger.c:   == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/ewrinf-b702dfc8'