[2009-03-06 11:08:49] VERBOSE[12525] logger.c: -- <SIP/8123457-b7c67bd8> Playing 'digits/0' (language 'en')
[2009-03-06 11:08:50] VERBOSE[12525] logger.c: -- <SIP/8123457-b7c67bd8> Playing 'vm-isunavail' (language 'en')
[2009-03-06 11:08:51] VERBOSE[12525] logger.c: -- <SIP/8123457-b7c67bd8> Playing 'vm-intro' (language 'en')
[2009-03-06 11:08:57] VERBOSE[12525] logger.c: -- <SIP/8123457-b7c67bd8> Playing 'beep' (language 'en')
[2009-03-06 11:08:57] VERBOSE[12525] logger.c: -- Recording the message
[2009-03-06 11:08:57] VERBOSE[12525] logger.c: -- x=0, open writing: /var/spool/asterisk/voicemail/default/500/tmp/ilJjaJ format: wav49, 0x855dbe8
[2009-03-06 11:08:57] VERBOSE[12525] logger.c: -- x=1, open writing: /var/spool/asterisk/voicemail/default/500/tmp/ilJjaJ format: wav, 0x8544da0
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: -- User hung up
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: == Spawn extension (macro-vm, s-NOANSWER, 2) exited non-zero on 'SIP/8123457-b7c67bd8' in macro 'vm'
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: == Spawn extension (macro-vm, s-NOANSWER, 2) exited non-zero on 'SIP/8123457-b7c67bd8'
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: -- Executing [h@macro-vm:1] Macro("SIP/8123457-b7c67bd8", "vm-notify|500") in new stack
[2009-03-06 11:09:18] DEBUG[12525] func_db.c: DB: vmnotify/500 not found in database.
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: -- Executing [s@macro-vm-notify:1] Set("SIP/8123457-b7c67bd8", "phonenumber=") in new stack
[2009-03-06 11:09:18] DEBUG[12525] app_macro.c: Executed application: Set
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: -- Executing [s@macro-vm-notify:2] GotoIf("SIP/8123457-b7c67bd8", "1?0:10") in new stack
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: -- Goto (macro-vm-notify,s,0)
[2009-03-06 11:09:18] DEBUG[12525] app_macro.c: Executed application: Gotoif
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: -- Executing [s@macro-vm:2] Set("SIP/8123457-b7c67bd8", "VMGAIN=""") in new stack
[2009-03-06 11:09:18] DEBUG[12525] func_db.c: DB: BLKVM/100/SIP/8123457-b7c67bd8 not found in database.
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: -- Executing [s@macro-vm:3] GotoIf("SIP/8123457-b7c67bd8", "1?vmx|1") in new stack
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: -- Goto (macro-vm,vmx,1)
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: -- Executing [vmx@macro-vm:1] GotoIf("SIP/8123457-b7c67bd8", "0?s-NOANSWER|1") in new stack
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: -- Executing [vmx@macro-vm:2] Set("SIP/8123457-b7c67bd8", "MODE=unavail") in new stack
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: -- Executing [vmx@macro-vm:3] GotoIf("SIP/8123457-b7c67bd8", "1?notdirect") in new stack
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: -- Goto (macro-vm,vmx,5)
[2009-03-06 11:09:18] DEBUG[12525] func_db.c: DB: AMPUSER/500/vmx/unavail/state not found in database.
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: -- Executing [vmx@macro-vm:5] NoOp("SIP/8123457-b7c67bd8", "Checking if ext 500 is enabled: ") in new stack
[2009-03-06 11:09:18] DEBUG[12525] func_db.c: DB: AMPUSER/500/vmx/unavail/state not found in database.
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: -- Executing [vmx@macro-vm:6] GotoIf("SIP/8123457-b7c67bd8", "1?s-NOANSWER|1") in new stack
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: -- Goto (macro-vm,s-NOANSWER,1)
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: -- Executing [s-NOANSWER@macro-vm:1] Macro("SIP/8123457-b7c67bd8", "get-vmcontext|500") in new stack
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: -- Executing [s@macro-get-vmcontext:1] Set("SIP/8123457-b7c67bd8", "VMCONTEXT=default") in new stack
[2009-03-06 11:09:18] DEBUG[12525] app_macro.c: Executed application: Set
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: -- Executing [s@macro-get-vmcontext:2] GotoIf("SIP/8123457-b7c67bd8", "0?200:300") in new stack
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: -- Goto (macro-get-vmcontext,s,300)
[2009-03-06 11:09:18] DEBUG[12525] app_macro.c: Executed application: GotoIf
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: -- Executing [s@macro-get-vmcontext:300] NoOp("SIP/8123457-b7c67bd8", "") in new stack
[2009-03-06 11:09:18] DEBUG[12525] app_macro.c: Executed application: NoOp
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: -- Executing [s@macro-vm:2] Set("SIP/8123457-b7c67bd8", "VMGAIN=""") in new stack
[2009-03-06 11:09:18] DEBUG[12525] func_db.c: DB: BLKVM/100/SIP/8123457-b7c67bd8 not found in database.
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: -- Executing [s@macro-vm:3] GotoIf("SIP/8123457-b7c67bd8", "1?vmx|1") in new stack
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: -- Goto (macro-vm,vmx,1)
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: -- Executing [vmx@macro-vm:1] GotoIf("SIP/8123457-b7c67bd8", "0?s-NOANSWER|1") in new stack
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: -- Executing [vmx@macro-vm:2] Set("SIP/8123457-b7c67bd8", "MODE=unavail") in new stack
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: -- Executing [vmx@macro-vm:3] GotoIf("SIP/8123457-b7c67bd8", "1?notdirect") in new stack
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: -- Goto (macro-vm,vmx,5)
[2009-03-06 11:09:18] DEBUG[12525] func_db.c: DB: AMPUSER/500/vmx/unavail/state not found in database.
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: -- Executing [vmx@macro-vm:5] NoOp("SIP/8123457-b7c67bd8", "Checking if ext 500 is enabled: ") in new stack
[2009-03-06 11:09:18] DEBUG[12525] func_db.c: DB: AMPUSER/500/vmx/unavail/state not found in database.
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: -- Executing [vmx@macro-vm:6] GotoIf("SIP/8123457-b7c67bd8", "1?s-NOANSWER|1") in new stack
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: -- Goto (macro-vm,s-NOANSWER,1)
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: -- Executing [s-NOANSWER@macro-vm:1] Macro("SIP/8123457-b7c67bd8", "get-vmcontext|500") in new stack
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: -- Executing [s@macro-get-vmcontext:1] Set("SIP/8123457-b7c67bd8", "VMCONTEXT=default") in new stack
[2009-03-06 11:09:18] DEBUG[12525] app_macro.c: Executed application: Set
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: -- Executing [s@macro-get-vmcontext:2] GotoIf("SIP/8123457-b7c67bd8", "0?200:300") in new stack
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: -- Goto (macro-get-vmcontext,s,300)
[2009-03-06 11:09:18] DEBUG[12525] app_macro.c: Executed application: GotoIf
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: -- Executing [s@macro-get-vmcontext:300] NoOp("SIP/8123457-b7c67bd8", "") in new stack
[2009-03-06 11:09:18] DEBUG[12525] app_macro.c: Executed application: NoOp
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: -- Executing [s@macro-vm:2] Set("SIP/8123457-b7c67bd8", "VMGAIN=""") in new stack
[2009-03-06 11:09:18] DEBUG[12525] func_db.c: DB: BLKVM/100/SIP/8123457-b7c67bd8 not found in database.
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: -- Executing [s@macro-vm:3] GotoIf("SIP/8123457-b7c67bd8", "1?vmx|1") in new stack
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: -- Goto (macro-vm,vmx,1)
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: -- Executing [vmx@macro-vm:1] GotoIf("SIP/8123457-b7c67bd8", "0?s-NOANSWER|1") in new stack
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: -- Executing [vmx@macro-vm:2] Set("SIP/8123457-b7c67bd8", "MODE=unavail") in new stack
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: -- Executing [vmx@macro-vm:3] GotoIf("SIP/8123457-b7c67bd8", "1?notdirect") in new stack
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: -- Goto (macro-vm,vmx,5)
[2009-03-06 11:09:18] DEBUG[12525] func_db.c: DB: AMPUSER/500/vmx/unavail/state not found in database.
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: -- Executing [vmx@macro-vm:5] NoOp("SIP/8123457-b7c67bd8", "Checking if ext 500 is enabled: ") in new stack
[2009-03-06 11:09:18] DEBUG[12525] func_db.c: DB: AMPUSER/500/vmx/unavail/state not found in database.
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: -- Executing [vmx@macro-vm:6] GotoIf("SIP/8123457-b7c67bd8", "1?s-NOANSWER|1") in new stack
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: -- Goto (macro-vm,s-NOANSWER,1)
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: -- Executing [s-NOANSWER@macro-vm:1] Macro("SIP/8123457-b7c67bd8", "get-vmcontext|500") in new stack
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: -- Executing [s@macro-get-vmcontext:1] Set("SIP/8123457-b7c67bd8", "VMCONTEXT=default") in new stack
[2009-03-06 11:09:18] DEBUG[12525] app_macro.c: Executed application: Set
[2009-03-06 11:09:18] VERBOSE[12525] logger.c: -- Executing [s@macro-get-vmcontext:2] GotoIf("SIP/8123457-b7c67bd8", "0?200:300") in new stack