How to ‘activate’ voicemail on an extension on asterisk-Freepbx

I have asterisk-Freepbx (Version 12) hosted on a debian 7 server. I have created an extension (Cisco IP phone SPA 504G). I am able to dial in and out. The extension is configured to go to voicemail if unanswered, busy or unavailable. However, if the extension is not answered, it goes to a busy signal and not the voicemail. When I look at the voicemail set up, it says it is 'unactivated'. I cant figure out how to get this to work or activate it.

Many thanks for any suggestions

Thanks – it was already enabled when I switched to Device and user mode. I disabled and then enabled it again – but no change.

When I go to settings>voicemail admin, this is what I see:
Jas <101> (default) [unactivated]

And the following:

Number of Accounts: 1 ( 0 / 1 / 0 )

Below is the verbose debug info:

[2014-06-30 20:17:35] DEBUG[3125] acl.c: For destination '888.777.666.111', our source 

address is 111.000.000.111.
[2014-06-30 20:17:35] DEBUG[3125] chan_sip.c: Target address 888.777.666.111:5060 is not 

local, substituting externaddr
[2014-06-30 20:17:35] DEBUG[3125] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 

111.000.000.111:5060
[2014-06-30 20:17:35] DEBUG[3125] chan_sip.c: Allocating new SIP dialog for dac7fd13-

7aac12b7@192.168.10.9 - NOTIFY (No RTP)
[2014-06-30 20:17:35] DEBUG[3125] chan_sip.c: **** Received NOTIFY (4) - Command in SIP 

NOTIFY
[2014-06-30 20:17:35] DEBUG[3125] chan_sip.c: Trying to put 'SIP/2.0 489' onto UDP socket 

destined for 888.777.666.111:5060
[2014-06-30 20:17:35] DEBUG[3125] chan_sip.c: SIP message could not be handled, bad request: 

dac7fd13-7aac12b7@192.168.10.9
[2014-06-30 20:17:35] DEBUG[3125] chan_sip.c: = Looking for Call ID: 

5a0f7e28743c71c77c90cbb0131c182f@111.000.000.111:5060 (Checking To) --From tag as5387a74c --

To-tag 22a0f837d6d0aeb9i0
[2014-06-30 20:17:35] DEBUG[3125] chan_sip.c: Acked pending invite 102
[2014-06-30 20:17:35] DEBUG[3125] chan_sip.c: Stopping retransmission on 

'5a0f7e28743c71c77c90cbb0131c182f@111.000.000.111:5060' of Request 102: Match Found
[2014-06-30 20:17:35] VERBOSE[3125] chan_sip.c: -- Got SIP response 486 "Busy Here" back from 

888.777.666.111:5060
[2014-06-30 20:17:35] DEBUG[3125] res_rtp_asterisk.c: Setting RTCP address on RTP instance 

'0x35b7eb8'
[2014-06-30 20:17:35] DEBUG[3125] netsock2.c: Splitting '192.168.10.9:5060' into...
[2014-06-30 20:17:35] DEBUG[3125] netsock2.c: ...host '192.168.10.9' and port '5060'.
[2014-06-30 20:17:35] DEBUG[3125] chan_sip.c: Trying to put 'ACK sip:101' onto UDP socket 

destined for 888.777.666.111:5060
[2014-06-30 20:17:35] DEBUG[3125] chan_sip.c: Setting SIP_ALREADYGONE on dialog 

5a0f7e28743c71c77c90cbb0131c182f@111.000.000.111:5060
[2014-06-30 20:17:35] VERBOSE[32392] app_dial.c: -- SIP/101-00004916 is busy
[2014-06-30 20:17:35] DEBUG[32392] channel.c: Hanging up channel 'SIP/101-00004916'
[2014-06-30 20:17:35] DEBUG[32392] chan_sip.c: Hanging up zombie call. Be scared.
[2014-06-30 20:17:35] DEBUG[32392] chan_sip.c: Updating call counter for outgoing call
[2014-06-30 20:17:35] DEBUG[32392] res_rtp_asterisk.c: Setting RTCP address on RTP instance 

'0x35b7eb8'
[2014-06-30 20:17:35] VERBOSE[32392] app_dial.c: == Everyone is busy/congested at this time 

(1:1/0/0)
[2014-06-30 20:17:35] DEBUG[32392] app_dial.c: Exiting with DIALSTATUS=BUSY.
[2014-06-30 20:17:35] DEBUG[32392] app_macro.c: Executed application: Dial
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'DIALSTATUS' is 'BUSY'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'CALLER_DEST' is NULL
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Expression result is '0'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Launching 'ExecIf'
[2014-06-30 20:17:35] VERBOSE[32392] pbx.c: -- Executing [s@macro-dial-one:43] ExecIf

("SIP/123456-00004915", "0?MacroExit()") in new stack
[2014-06-30 20:17:35] DEBUG[32392] app_macro.c: Executed application: ExecIf
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Evaluating 'DIALSTATUS' (from 

'DIALSTATUS}"="ANSWER" & "${CALLER_DEST}"!=""' len 10)
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'DIALSTATUS' is 'BUSY'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Evaluating 'CALLER_DEST' (from 'CALLER_DEST}"!=""' 

len 11)
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'CALLER_DEST' is NULL
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Expression result is '0'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'DIALSTATUS_CW' is ''
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Expression result is '0'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'DIALSTATUS_CW' is ''
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Launching 'ExecIf'
[2014-06-30 20:17:35] VERBOSE[32392] pbx.c: -- Executing [s@macro-dial-one:44] ExecIf

("SIP/123456-00004915", "0?Set(DIALSTATUS=)") in new stack
[2014-06-30 20:17:35] DEBUG[32392] app_macro.c: Executed application: ExecIf
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Evaluating 'DIALSTATUS_CW' (from 'DIALSTATUS_CW}"!

=""' len 13)
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'DIALSTATUS_CW' is ''
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Expression result is '0'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Evaluating 'DIALSTATUS_CW' (from 'DIALSTATUS_CW})' 

len 13)
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'DIALSTATUS_CW' is ''
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'SCREEN' is NULL
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'DIALSTATUS' is 'BUSY'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'DIALSTATUS' is 'BUSY'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'DIALSTATUS' is 'BUSY'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Expression result is '0'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'DIALSTATUS' is 'BUSY'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Launching 'GosubIf'
[2014-06-30 20:17:35] VERBOSE[32392] pbx.c: -- Executing [s@macro-dial-one:45] GosubIf

("SIP/123456-00004915", "0?s-BUSY,1()") in new stack
[2014-06-30 20:17:35] DEBUG[32392] app_macro.c: Executed application: GosubIf
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Evaluating 'SCREEN' (from 'SCREEN}"!=""&

("${DIALSTATUS}"="TORTURE"|"${DIALSTATUS}"="DONTCALL"))|"${DIALSTATUS}"="ANSWER"' len 6)
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'SCREEN' is NULL
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Evaluating 'DIALSTATUS' (from 

'DIALSTATUS}"="TORTURE"|"${DIALSTATUS}"="DONTCALL"))|"${DIALSTATUS}"="ANSWER"' len 10)
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'DIALSTATUS' is 'BUSY'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Evaluating 'DIALSTATUS' (from 

'DIALSTATUS}"="DONTCALL"))|"${DIALSTATUS}"="ANSWER"' len 10)
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'DIALSTATUS' is 'BUSY'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Evaluating 'DIALSTATUS' (from 

'DIALSTATUS}"="ANSWER"' len 10)
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'DIALSTATUS' is 'BUSY'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Expression result is '0'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Evaluating 'DIALSTATUS' (from 'DIALSTATUS},1()' len 

10)
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'DIALSTATUS' is 'BUSY'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Launching 'MacroExit'
[2014-06-30 20:17:35] VERBOSE[32392] pbx.c: -- Executing [s@macro-dial-one:46] MacroExit

("SIP/123456-00004915", "") in new stack
[2014-06-30 20:17:35] DEBUG[32392] app_macro.c: Executed application: Macro
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'DIALSTATUS' is 'BUSY'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Launching 'Set'
[2014-06-30 20:17:35] VERBOSE[32392] pbx.c: -- Executing [s@macro-exten-vm:15] Set

("SIP/123456-00004915", "SV_DIALSTATUS=BUSY") in new stack
[2014-06-30 20:17:35] DEBUG[32392] app_macro.c: Executed application: Set
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'SV_DIALSTATUS' is 'BUSY'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'SV_DIALSTATUS' is 'BUSY'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'EXTTOCALL' is '101'
[2014-06-30 20:17:35] DEBUG[32392] db.c: Unable to find key '101' in family 'CFU'
[2014-06-30 20:17:35] DEBUG[32392] func_db.c: DB: CFU/101 not found in database.
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Function result is ''
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'SCREEN' is NULL
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Expression result is '0'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Launching 'GosubIf'
[2014-06-30 20:17:35] VERBOSE[32392] pbx.c: -- Executing [s@macro-exten-vm:16] GosubIf

("SIP/123456-00004915", "0?docfu,1()") in new stack
[2014-06-30 20:17:35] DEBUG[32392] app_macro.c: Executed application: GosubIf
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Evaluating 'SV_DIALSTATUS' (from 

'SV_DIALSTATUS}"="NOANSWER"|"${SV_DIALSTATUS}"="CHANUNAVAIL") & "${DB(CFU/${EXTTOCALL})}"!="" 

& "${SCREEN}"=""' len 13)
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'SV_DIALSTATUS' is 'BUSY'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Evaluating 'SV_DIALSTATUS' (from 

'SV_DIALSTATUS}"="CHANUNAVAIL") & "${DB(CFU/${EXTTOCALL})}"!="" & "${SCREEN}"=""' len 13)
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'SV_DIALSTATUS' is 'BUSY'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Evaluating 'DB(CFU/${EXTTOCALL})' (from 'DB(CFU/

${EXTTOCALL})}"!="" & "${SCREEN}"=""' len 20)
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Evaluating 'EXTTOCALL' (from 'EXTTOCALL})' len 9)
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'EXTTOCALL' is '101'
[2014-06-30 20:17:35] DEBUG[32392] db.c: Unable to find key '101' in family 'CFU'
[2014-06-30 20:17:35] DEBUG[32392] func_db.c: DB: CFU/101 not found in database.
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Function result is ''
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Evaluating 'SCREEN' (from 'SCREEN}"=""' len 6)
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'SCREEN' is NULL
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Expression result is '0'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'SV_DIALSTATUS' is 'BUSY'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'EXTTOCALL' is '101'
[2014-06-30 20:17:35] DEBUG[32392] db.c: Unable to find key '101' in family 'CFB'
[2014-06-30 20:17:35] DEBUG[32392] func_db.c: DB: CFB/101 not found in database.
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Function result is ''
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'SCREEN' is NULL
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Expression result is '0'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Launching 'GosubIf'
[2014-06-30 20:17:35] VERBOSE[32392] pbx.c: -- Executing [s@macro-exten-vm:17] GosubIf

("SIP/123456-00004915", "0?docfb,1()") in new stack
[2014-06-30 20:17:35] DEBUG[32392] app_macro.c: Executed application: GosubIf
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Evaluating 'SV_DIALSTATUS' (from 

'SV_DIALSTATUS}"="BUSY" & "${DB(CFB/${EXTTOCALL})}"!="" & "${SCREEN}"=""' len 13)
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'SV_DIALSTATUS' is 'BUSY'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Evaluating 'DB(CFB/${EXTTOCALL})' (from 'DB(CFB/

${EXTTOCALL})}"!="" & "${SCREEN}"=""' len 20)
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Evaluating 'EXTTOCALL' (from 'EXTTOCALL})' len 9)
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'EXTTOCALL' is '101'
[2014-06-30 20:17:35] DEBUG[32392] db.c: Unable to find key '101' in family 'CFB'
[2014-06-30 20:17:35] DEBUG[32392] func_db.c: DB: CFB/101 not found in database.
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Function result is ''
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Evaluating 'SCREEN' (from 'SCREEN}"=""' len 6)
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'SCREEN' is NULL
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Expression result is '0'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'SV_DIALSTATUS' is 'BUSY'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Launching 'Set'
[2014-06-30 20:17:35] VERBOSE[32392] pbx.c: -- Executing [s@macro-exten-vm:18] Set

("SIP/123456-00004915", "DIALSTATUS=BUSY") in new stack
[2014-06-30 20:17:35] DEBUG[32392] app_macro.c: Executed application: Set
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'DIALSTATUS' is 'BUSY'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'ARG3' is '1'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'DIALSTATUS' is 'BUSY'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'ARG4' is '1'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'DIALSTATUS' is 'BUSY'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'ARG5' is '1'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Expression result is '1'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Launching 'ExecIf'
[2014-06-30 20:17:35] VERBOSE[32392] pbx.c: -- Executing [s@macro-exten-vm:19] ExecIf

("SIP/123456-00004915", "1?MacroExit()") in new stack
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Launching 'Set'
[2014-06-30 20:17:35] VERBOSE[32392] pbx.c: -- Executing [101@from-did-direct:3] Set

("SIP/123456-00004915", "__PICKUPMARK=") in new stack
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'DIALSTATUS' is 'BUSY'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Expression result is '0'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Launching 'GotoIf'
[2014-06-30 20:17:35] VERBOSE[32392] pbx.c: -- Executing [101@from-did-direct:4] GotoIf

("SIP/123456-00004915", "0?ext-local,vmu101,1") in new stack
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Not taking any branch
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'DIALSTATUS' is 'BUSY'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Expression result is '1'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Launching 'GotoIf'
[2014-06-30 20:17:35] VERBOSE[32392] pbx.c: -- Executing [101@from-did-direct:5] GotoIf

("SIP/123456-00004915", "1?ext-local,vmb101,1") in new stack
[2014-06-30 20:17:35] VERBOSE[32392] pbx.c: -- Goto (ext-local,vmb101,1)
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'IVR_RETVM' is NULL
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Launching 'Macro'
[2014-06-30 20:17:35] VERBOSE[32392] pbx.c: -- Executing [vmb101@ext-local:1] Macro

("SIP/123456-00004915", "vm,101,BUSY,") in new stack
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Launching 'Macro'
[2014-06-30 20:17:35] VERBOSE[32392] pbx.c: -- Executing [s@macro-vm:1] Macro("SIP/123456-

00004915", "user-callerid,SKIPTTL") in new stack
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'UNIQUEID' is '1404159446.4576'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Launching 'Set'
[2014-06-30 20:17:35] VERBOSE[32392] pbx.c: -- Executing [s@macro-user-callerid:1] Set

("SIP/123456-00004915", "TOUCH_MONITOR=1404159446.4576") in new stack
[2014-06-30 20:17:35] DEBUG[32392] app_macro.c: Executed application: Set
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'AMPUSER' is ''
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Expression result is '1'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Function result is '5401112222'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'AMPUSER' is ''
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Function result is '5401112222'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Launching 'Set'
[2014-06-30 20:17:35] VERBOSE[32392] pbx.c: -- Executing [s@macro-user-callerid:2] Set

("SIP/123456-00004915", "AMPUSER=5401112222") in new stack
[2014-06-30 20:17:35] DEBUG[32392] app_macro.c: Executed application: Set
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Evaluating 'CHANNEL' (from 'CHANNEL}' len 7)
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'CHANNEL' is 'SIP/123456-00004915'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Function result is ''
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'AMPUSERCIDNAME' is ''
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Function result is '0'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Expression result is '0'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Launching 'GotoIf'
[2014-06-30 20:17:35] VERBOSE[32392] pbx.c: -- Executing [s@macro-user-callerid:3] GotoIf

("SIP/123456-00004915", "0?report") in new stack
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Not taking any branch
[2014-06-30 20:17:35] DEBUG[32392] app_macro.c: Executed application: GotoIf
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'REALCALLERIDNUM' is '5401112222'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Expression result is '0'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Function result is '5401112222'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Launching 'ExecIf'
[2014-06-30 20:17:35] VERBOSE[32392] pbx.c: -- Executing [s@macro-user-callerid:4] ExecIf

("SIP/123456-00004915", "0?Set(REALCALLERIDNUM=5401112222)") in new stack
[2014-06-30 20:17:35] DEBUG[32392] app_macro.c: Executed application: ExecIf
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Evaluating 'REALCALLERIDNUM:1:2' (from 

'REALCALLERIDNUM:1:2}" = ""' len 19)
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'REALCALLERIDNUM' is '5401112222'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Expression result is '0'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Evaluating 'CALLERID(number)' (from 'CALLERID

(number)})' len 16)
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Function result is '5401112222'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'REALCALLERIDNUM' is '5401112222'
[2014-06-30 20:17:35] DEBUG[32392] db.c: Unable to find key '5401112222/user' in family 

'DEVICE'
[2014-06-30 20:17:35] DEBUG[32392] func_db.c: DB: DEVICE/5401112222/user not found in 

database.
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Function result is ''
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Launching 'Set'
[2014-06-30 20:17:35] VERBOSE[32392] pbx.c: -- Executing [s@macro-user-callerid:5] Set

("SIP/123456-00004915", "AMPUSER=") in new stack
[2014-06-30 20:17:35] DEBUG[32392] app_macro.c: Executed application: Set
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'AMPUSER' is ''
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Expression result is '0'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Launching 'GotoIf'
[2014-06-30 20:17:35] VERBOSE[32392] pbx.c: -- Executing [s@macro-user-callerid:6] GotoIf

("SIP/123456-00004915", "0?limit") in new stack
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Not taking any branch
[2014-06-30 20:17:35] DEBUG[32392] app_macro.c: Executed application: GotoIf
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'AMPUSER' is ''
[2014-06-30 20:17:35] DEBUG[32392] db.c: Unable to find key '/cidname' in family 'AMPUSER'
[2014-06-30 20:17:35] DEBUG[32392] func_db.c: DB: AMPUSER//cidname not found in database.
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Function result is ''
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Launching 'Set'
[2014-06-30 20:17:35] VERBOSE[32392] pbx.c: -- Executing [s@macro-user-callerid:7] Set

("SIP/123456-00004915", "AMPUSERCIDNAME=") in new stack
[2014-06-30 20:17:35] DEBUG[32392] app_macro.c: Executed application: Set
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'AMPUSERCIDNAME' is ''
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Expression result is '1'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Launching 'GotoIf'
[2014-06-30 20:17:35] VERBOSE[32392] pbx.c: -- Executing [s@macro-user-callerid:8] GotoIf

("SIP/123456-00004915", "1?report") in new stack
[2014-06-30 20:17:35] VERBOSE[32392] pbx.c: -- Goto (macro-user-callerid,s,16)
[2014-06-30 20:17:35] DEBUG[32392] app_macro.c: Executed application: GotoIf
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'ARG1' is 'SKIPTTL'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'ARG1' is 'SKIPTTL'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Expression result is '1'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Launching 'GotoIf'
[2014-06-30 20:17:35] VERBOSE[32392] pbx.c: -- Executing [s@macro-user-callerid:16] GotoIf

("SIP/123456-00004915", "1?continue") in new stack
[2014-06-30 20:17:35] VERBOSE[32392] pbx.c: -- Goto (macro-user-callerid,s,30)
[2014-06-30 20:17:35] DEBUG[32392] app_macro.c: Executed application: GotoIf
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Function result is '5401112222'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Launching 'Set'
[2014-06-30 20:17:35] VERBOSE[32392] pbx.c: -- Executing [s@macro-user-callerid:30] Set

("SIP/123456-00004915", "CALLERID(number)=5401112222") in new stack
[2014-06-30 20:17:35] DEBUG[32392] app_macro.c: Executed application: Set
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Function result is '+15401112222'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Launching 'Set'
[2014-06-30 20:17:35] VERBOSE[32392] pbx.c: -- Executing [s@macro-user-callerid:31] Set

("SIP/123456-00004915", "CALLERID(name)=+15401112222") in new stack
[2014-06-30 20:17:35] DEBUG[32392] app_macro.c: Executed application: Set
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Function result is '5401112222'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Launching 'Set'
[2014-06-30 20:17:35] VERBOSE[32392] pbx.c: -- Executing [s@macro-user-callerid:32] Set

("SIP/123456-00004915", "CDR(cnum)=5401112222") in new stack
[2014-06-30 20:17:35] DEBUG[32392] app_macro.c: Executed application: Set
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Function result is '+15401112222'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Launching 'Set'
[2014-06-30 20:17:35] VERBOSE[32392] pbx.c: -- Executing [s@macro-user-callerid:33] Set

("SIP/123456-00004915", "CDR(cnam)=+15401112222") in new stack
[2014-06-30 20:17:35] DEBUG[32392] app_macro.c: Executed application: Set
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Evaluating 'CHANNEL(language)' (from 'CHANNEL

(language)}' len 17)
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Function result is 'en'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Function result is 'en'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Launching 'Set'
[2014-06-30 20:17:35] VERBOSE[32392] pbx.c: -- Executing [s@macro-user-callerid:34] Set

("SIP/123456-00004915", "CHANNEL(language)=en") in new stack
[2014-06-30 20:17:35] DEBUG[32392] app_macro.c: Executed application: Set
[2014-06-30 20:17:35] DEBUG[32392] app_macro.c: Executed application: Macro
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'VM_GAIN' is '12'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Expression result is '1'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'VM_GAIN' is '12'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Function result is 'g(12)'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Launching 'Set'
[2014-06-30 20:17:35] VERBOSE[32392] pbx.c: -- Executing [s@macro-vm:2] Set("SIP/123456-

00004915", "VMGAIN=g(12)") in new stack
[2014-06-30 20:17:35] DEBUG[32392] app_macro.c: Executed application: Set
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Launching 'Macro'
[2014-06-30 20:17:35] VERBOSE[32392] pbx.c: -- Executing [s@macro-vm:3] Macro("SIP/123456-

00004915", "blkvm-check,") in new stack
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'BLKVM_CHANNEL' is NULL
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Function result is '(null)'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Launching 'Set'
[2014-06-30 20:17:35] VERBOSE[32392] pbx.c: -- Executing [s@macro-blkvm-check:1] Set

("SIP/123456-00004915", "GOSUB_RETVAL=") in new stack
[2014-06-30 20:17:35] DEBUG[32392] app_macro.c: Executed application: Set
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'GOSUB_RETVAL' is ''
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'CC_RECALL' is NULL
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Expression result is '0'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Launching 'ExecIf'
[2014-06-30 20:17:35] VERBOSE[32392] pbx.c: -- Executing [s@macro-blkvm-check:2] ExecIf

("SIP/123456-00004915", "0?Set(GOSUB_RETVAL=TRUE)") in new stack
[2014-06-30 20:17:35] DEBUG[32392] app_macro.c: Executed application: ExecIf
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Evaluating 'GOSUB_RETVAL' (from 'GOSUB_RETVAL}"="" 

& "${CC_RECALL}"="1"' len 12)
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'GOSUB_RETVAL' is ''
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Evaluating 'CC_RECALL' (from 'CC_RECALL}"="1"' len 

9)
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Result of 'CC_RECALL' is NULL
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Expression result is '0'
[2014-06-30 20:17:35] DEBUG[32392] pbx.c: Launching 'MacroExit'
[2014-06-30 20:17:35] VERBOSE[32392] pbx.c: -- Executing [s@macro-blkvm-check:3] MacroExit