[Jul 30 13:55:13] DEBUG[21500] chan_sip.c: Allocating new SIP dialog for 4721fea635f2ef31610f8a60578778e0@156.150.133.165 - OPTIONS (No RTP)
[Jul 30 13:55:13] DEBUG[21500] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 156.150.133.165:5060
[Jul 30 13:55:40] DEBUG[21500] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jul 30 13:55:40] DEBUG[21500] chan_sip.c: Initializing initreq for method OPTIONS - callid 09ed4204182414f2159c982c5b7707b9@156.150.132.46
[Jul 30 13:55:40] DEBUG[21500] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 156.150.133.165:5060
[Jul 30 13:55:40] DEBUG[21500] chan_sip.c: Stopping retransmission on '09ed4204182414f2159c982c5b7707b9@156.150.132.46' of Request 102: Match Found
[Jul 30 13:56:13] DEBUG[21500] chan_sip.c: Allocating new SIP dialog for 4c2914c31a0c00a8103a359424880d8a@156.150.133.165 - OPTIONS (No RTP)
[Jul 30 13:56:13] DEBUG[21500] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 156.150.133.165:5060
[Jul 30 13:56:40] DEBUG[21500] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jul 30 13:56:40] DEBUG[21500] chan_sip.c: Initializing initreq for method OPTIONS - callid 1a68afad52fe18ca4bc6862940a16e77@156.150.132.46
[Jul 30 13:56:40] DEBUG[21500] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 156.150.133.165:5060
[Jul 30 13:56:40] DEBUG[21500] chan_sip.c: Stopping retransmission on '1a68afad52fe18ca4bc6862940a16e77@156.150.132.46' of Request 102: Match Found
[Jul 30 13:56:45] VERBOSE[21500] logger.c:   == Using SIP RTP TOS bits 184
[Jul 30 13:56:45] VERBOSE[21500] logger.c:   == Using SIP RTP CoS mark 5
[Jul 30 13:56:45] VERBOSE[21500] logger.c:   == Using SIP VRTP TOS bits 136
[Jul 30 13:56:45] VERBOSE[21500] logger.c:   == Using SIP VRTP CoS mark 6
[Jul 30 13:56:45] DEBUG[21500] chan_sip.c: Setting NAT on RTP to Off
[Jul 30 13:56:45] DEBUG[21500] chan_sip.c: Setting NAT on VRTP to Off
[Jul 30 13:56:45] DEBUG[21500] chan_sip.c: Allocating new SIP dialog for 7bcedf89276171fc6abfb467787093e8@156.150.133.165 - INVITE (With RTP)
[Jul 30 13:56:45] DEBUG[21500] chan_sip.c: Setting NAT on RTP to Off
[Jul 30 13:56:45] DEBUG[21500] chan_sip.c: Setting NAT on VRTP to Off
[Jul 30 13:56:45] DEBUG[21500] chan_sip.c: Checking SIP call limits for device esn
[Jul 30 13:56:45] DEBUG[21500] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 156.150.133.165:5060
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'Macro'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [9999@from-internal:1] Macro("SIP/Proxy_ESN-00000000", "exten-vm,9999,9999") in new stack
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'Macro'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-exten-vm:1] Macro("SIP/Proxy_ESN-00000000", "user-callerid") in new stack
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '1'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Function result is '008029'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Function result is '008029'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'Set'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-user-callerid:1] Set("SIP/Proxy_ESN-00000000", "AMPUSER=008029") in new stack
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: Set
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '0'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'GotoIf'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-user-callerid:2] GotoIf("SIP/Proxy_ESN-00000000", "0?report") in new stack
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Not taking any branch
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: GotoIf
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '1'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Function result is '008029'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'ExecIf'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-user-callerid:3] ExecIf("SIP/Proxy_ESN-00000000", "1?Set(REALCALLERIDNUM=008029)") in new stack
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: ExecIf
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '0'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Function result is '008029'
[Jul 30 13:56:45] DEBUG[21534] db.c: Unable to find key '008029/user' in family 'DEVICE'
[Jul 30 13:56:45] DEBUG[21534] func_db.c: DB: DEVICE/008029/user not found in database.
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Function result is ''
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'Set'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-user-callerid:4] Set("SIP/Proxy_ESN-00000000", "AMPUSER=") in new stack
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: Set
[Jul 30 13:56:45] DEBUG[21534] db.c: Unable to find key '/cidname' in family 'AMPUSER'
[Jul 30 13:56:45] DEBUG[21534] func_db.c: DB: AMPUSER//cidname not found in database.
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Function result is ''
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'Set'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-user-callerid:5] Set("SIP/Proxy_ESN-00000000", "AMPUSERCIDNAME=") in new stack
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: Set
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '1'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'GotoIf'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-user-callerid:6] GotoIf("SIP/Proxy_ESN-00000000", "1?report") in new stack
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Goto (macro-user-callerid,s,10)
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: GotoIf
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '0'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'GotoIf'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-user-callerid:10] GotoIf("SIP/Proxy_ESN-00000000", "0?continue") in new stack
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Not taking any branch
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: GotoIf
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '1'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '-1'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Function result is '64'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'Set'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-user-callerid:11] Set("SIP/Proxy_ESN-00000000", "__TTL=64") in new stack
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: Set
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '1'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'GotoIf'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-user-callerid:12] GotoIf("SIP/Proxy_ESN-00000000", "1?continue") in new stack
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Goto (macro-user-callerid,s,19)
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: GotoIf
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Function result is '"GUTZKE KLAUS" <008029>'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'NoOp'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-user-callerid:19] NoOp("SIP/Proxy_ESN-00000000", "Using CallerID "GUTZKE KLAUS" <008029>") in new stack
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: Noop
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: Macro
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'Set'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-exten-vm:2] Set("SIP/Proxy_ESN-00000000", "RingGroupMethod=none") in new stack
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: Set
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'Set'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-exten-vm:3] Set("SIP/Proxy_ESN-00000000", "VMBOX=9999") in new stack
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: Set
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'Set'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-exten-vm:4] Set("SIP/Proxy_ESN-00000000", "EXTTOCALL=9999") in new stack
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: Set
[Jul 30 13:56:45] DEBUG[21534] db.c: Unable to find key '9999' in family 'CFU'
[Jul 30 13:56:45] DEBUG[21534] func_db.c: DB: CFU/9999 not found in database.
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Function result is ''
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'Set'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-exten-vm:5] Set("SIP/Proxy_ESN-00000000", "CFUEXT=") in new stack
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: Set
[Jul 30 13:56:45] DEBUG[21534] db.c: Unable to find key '9999' in family 'CFB'
[Jul 30 13:56:45] DEBUG[21534] func_db.c: DB: CFB/9999 not found in database.
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Function result is ''
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'Set'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-exten-vm:6] Set("SIP/Proxy_ESN-00000000", "CFBEXT=") in new stack
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: Set
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '1'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '0'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '1'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Function result is '15'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'Set'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-exten-vm:7] Set("SIP/Proxy_ESN-00000000", "RT=15") in new stack
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: Set
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'Macro'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-exten-vm:8] Macro("SIP/Proxy_ESN-00000000", "record-enable,9999,IN") in new stack
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '1'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'GotoIf'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-record-enable:1] GotoIf("SIP/Proxy_ESN-00000000", "1?check") in new stack
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Goto (macro-record-enable,s,4)
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: GotoIf
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Function result is '20100730-135645'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'AGI'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-record-enable:4] AGI("SIP/Proxy_ESN-00000000", "recordingcheck,20100730-135645,1280491005.0") in new stack
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
[Jul 30 13:56:45] VERBOSE[21534] logger.c:  recordingcheck,20100730-135645,1280491005.0: Inbound recording not enabled
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- <SIP/Proxy_ESN-00000000>AGI Script recordingcheck completed, returning 0
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: AGI
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'MacroExit'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-record-enable:5] MacroExit("SIP/Proxy_ESN-00000000", "") in new stack
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: Macro
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'Macro'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-exten-vm:9] Macro("SIP/Proxy_ESN-00000000", "dial,15,tr,9999") in new stack
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '1'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'GotoIf'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-dial:1] GotoIf("SIP/Proxy_ESN-00000000", "1?dial") in new stack
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Goto (macro-dial,s,3)
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: GotoIf
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'AGI'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-dial:3] AGI("SIP/Proxy_ESN-00000000", "dialparties.agi") in new stack
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
[Jul 30 13:56:45] VERBOSE[21534] logger.c:  dialparties.agi: Starting New Dialparties.agi
[Jul 30 13:56:45] VERBOSE[21534] logger.c:  dialparties.agi: Caller ID name is 'GUTZKE KLAUS' number is '008029'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:        > dialparties.agi: USE_CONFIRMATION:  'FALSE'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:        > dialparties.agi: RINGGROUP_INDEX:   ''
[Jul 30 13:56:45] VERBOSE[21534] logger.c:  dialparties.agi: Methodology of ring is  'none'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- dialparties.agi: Added extension 9999 to extension map
[Jul 30 13:56:45] DEBUG[21534] db.c: Unable to find key '9999' in family 'CF'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- dialparties.agi: Extension 9999 cf is disabled
[Jul 30 13:56:45] DEBUG[21534] db.c: Unable to find key '9999' in family 'DND'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- dialparties.agi: Extension 9999 do not disturb is disabled
[Jul 30 13:56:45] DEBUG[21534] db.c: Unable to find key '9999' in family 'CFB'
[Jul 30 13:56:45] DEBUG[21534] db.c: Unable to find key '9999' in family 'CFU'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:        > dialparties.agi: extnum 9999 has:  cw: 1; hascfb: 0 [] hascfu: 0 []
[Jul 30 13:56:45] DEBUG[21534] db.c: Unable to find key 'DND9999' in family 'CustomDevstate'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:  dialparties.agi: EXTENSION_STATE: 4 (UNAVAILABLE)
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- dialparties.agi: dbset CALLTRACE/9999 to 008029
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- dialparties.agi: Filtered ARG3: 9999
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- <SIP/Proxy_ESN-00000000>AGI Script dialparties.agi completed, returning 0
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: AGI
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'Dial'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-dial:7] Dial("SIP/Proxy_ESN-00000000", "SIP/9999,15,tr") in new stack
[Jul 30 13:56:45] DEBUG[21534] chan_sip.c: Asked to create a SIP channel with formats: 0x280004 (ulaw|h263|h264)
[Jul 30 13:56:45] VERBOSE[21534] logger.c:   == Using SIP RTP TOS bits 184
[Jul 30 13:56:45] VERBOSE[21534] logger.c:   == Using SIP RTP CoS mark 5
[Jul 30 13:56:45] VERBOSE[21534] logger.c:   == Using SIP VRTP TOS bits 136
[Jul 30 13:56:45] VERBOSE[21534] logger.c:   == Using SIP VRTP CoS mark 6
[Jul 30 13:56:45] DEBUG[21534] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
[Jul 30 13:56:45] WARNING[21534] app_dial.c: Unable to create channel of type 'SIP' (cause 20 - Unknown)
[Jul 30 13:56:45] VERBOSE[21534] logger.c:   == Everyone is busy/congested at this time (1:0/0/1)
[Jul 30 13:56:45] DEBUG[21534] rtp.c: Channel '<unspecified>' has no RTP, not doing anything
[Jul 30 13:56:45] DEBUG[21534] app_dial.c: Exiting with DIALSTATUS=CHANUNAVAIL.
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: Dial
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '0'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Function result is 'CHANUNAVAIL'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'Set'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-dial:8] Set("SIP/Proxy_ESN-00000000", "DIALSTATUS=CHANUNAVAIL") in new stack
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: Set
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '0'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'GosubIf'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-dial:9] GosubIf("SIP/Proxy_ESN-00000000", "0?CHANUNAVAIL,1") in new stack
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: GosubIf
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '0'
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: Macro
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '1'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '0'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '0'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '0'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'GotoIf'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-exten-vm:10] GotoIf("SIP/Proxy_ESN-00000000", "0?exit,return") in new stack
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Not taking any branch
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: GotoIf
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'Set'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-exten-vm:11] Set("SIP/Proxy_ESN-00000000", "SV_DIALSTATUS=CHANUNAVAIL") in new stack
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: Set
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '0'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '0'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '1'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '0'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'GosubIf'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-exten-vm:12] GosubIf("SIP/Proxy_ESN-00000000", "0?docfu,1") in new stack
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: GosubIf
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '0'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '0'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '1'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '0'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '0'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '0'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '0'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'GosubIf'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-exten-vm:13] GosubIf("SIP/Proxy_ESN-00000000", "0?docfb,1") in new stack
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: GosubIf
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '0'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '0'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '0'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'Set'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-exten-vm:14] Set("SIP/Proxy_ESN-00000000", "DIALSTATUS=CHANUNAVAIL") in new stack
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: Set
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'NoOp'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-exten-vm:15] NoOp("SIP/Proxy_ESN-00000000", "Voicemail is '9999'") in new stack
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: NoOp
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '0'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'GotoIf'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-exten-vm:16] GotoIf("SIP/Proxy_ESN-00000000", "0?s-CHANUNAVAIL,1") in new stack
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Not taking any branch
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: GotoIf
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'NoOp'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-exten-vm:17] NoOp("SIP/Proxy_ESN-00000000", "Sending to Voicemail box 9999") in new stack
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: NoOp
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'Macro'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-exten-vm:18] Macro("SIP/Proxy_ESN-00000000", "vm,9999,CHANUNAVAIL,") in new stack
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'Macro'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-vm:1] Macro("SIP/Proxy_ESN-00000000", "user-callerid,SKIPTTL") in new stack
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '1'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Function result is '008029'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Function result is '008029'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'Set'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-user-callerid:1] Set("SIP/Proxy_ESN-00000000", "AMPUSER=008029") in new stack
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: Set
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '0'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'GotoIf'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-user-callerid:2] GotoIf("SIP/Proxy_ESN-00000000", "0?report") in new stack
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Not taking any branch
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: GotoIf
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '0'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Function result is '008029'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'ExecIf'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-user-callerid:3] ExecIf("SIP/Proxy_ESN-00000000", "0?Set(REALCALLERIDNUM=008029)") in new stack
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: ExecIf
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '0'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Function result is '008029'
[Jul 30 13:56:45] DEBUG[21534] db.c: Unable to find key '008029/user' in family 'DEVICE'
[Jul 30 13:56:45] DEBUG[21534] func_db.c: DB: DEVICE/008029/user not found in database.
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Function result is ''
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'Set'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-user-callerid:4] Set("SIP/Proxy_ESN-00000000", "AMPUSER=") in new stack
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: Set
[Jul 30 13:56:45] DEBUG[21534] db.c: Unable to find key '/cidname' in family 'AMPUSER'
[Jul 30 13:56:45] DEBUG[21534] func_db.c: DB: AMPUSER//cidname not found in database.
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Function result is ''
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'Set'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-user-callerid:5] Set("SIP/Proxy_ESN-00000000", "AMPUSERCIDNAME=") in new stack
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: Set
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '1'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'GotoIf'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-user-callerid:6] GotoIf("SIP/Proxy_ESN-00000000", "1?report") in new stack
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Goto (macro-user-callerid,s,10)
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: GotoIf
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '1'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'GotoIf'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-user-callerid:10] GotoIf("SIP/Proxy_ESN-00000000", "1?continue") in new stack
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Goto (macro-user-callerid,s,19)
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: GotoIf
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Function result is '"GUTZKE KLAUS" <008029>'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'NoOp'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-user-callerid:19] NoOp("SIP/Proxy_ESN-00000000", "Using CallerID "GUTZKE KLAUS" <008029>") in new stack
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: Noop
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: Macro
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '0'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Function result is '""'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'Set'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-vm:2] Set("SIP/Proxy_ESN-00000000", "VMGAIN=""") in new stack
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: Set
[Jul 30 13:56:45] WARNING[21534] func_db.c: DB requires an argument, DB(<family>/<key>)
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Function result is '(null)'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '1'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'GotoIf'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-vm:3] GotoIf("SIP/Proxy_ESN-00000000", "1?vmx,1") in new stack
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Goto (macro-vm,vmx,1)
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: GotoIf
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '0'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'GotoIf'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [vmx@macro-vm:1] GotoIf("SIP/Proxy_ESN-00000000", "0?s-CHANUNAVAIL,1") in new stack
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Not taking any branch
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: GotoIf
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '0'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Function result is 'unavail'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'Set'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [vmx@macro-vm:2] Set("SIP/Proxy_ESN-00000000", "MODE=unavail") in new stack
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: Set
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '1'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'GotoIf'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [vmx@macro-vm:3] GotoIf("SIP/Proxy_ESN-00000000", "1?notdirect") in new stack
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Goto (macro-vm,vmx,5)
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: GotoIf
[Jul 30 13:56:45] DEBUG[21534] db.c: Unable to find key '9999/vmx/unavail/state' in family 'AMPUSER'
[Jul 30 13:56:45] DEBUG[21534] func_db.c: DB: AMPUSER/9999/vmx/unavail/state not found in database.
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Function result is ''
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'NoOp'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [vmx@macro-vm:5] NoOp("SIP/Proxy_ESN-00000000", "Checking if ext 9999 is enabled: ") in new stack
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: Noop
[Jul 30 13:56:45] DEBUG[21534] db.c: Unable to find key '9999/vmx/unavail/state' in family 'AMPUSER'
[Jul 30 13:56:45] DEBUG[21534] func_db.c: DB: AMPUSER/9999/vmx/unavail/state not found in database.
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Function result is ''
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '1'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'GotoIf'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [vmx@macro-vm:6] GotoIf("SIP/Proxy_ESN-00000000", "1?s-CHANUNAVAIL,1") in new stack
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Goto (macro-vm,s-CHANUNAVAIL,1)
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: GotoIf
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'Macro'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s-CHANUNAVAIL@macro-vm:1] Macro("SIP/Proxy_ESN-00000000", "get-vmcontext,9999") in new stack
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Function result is 'default'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'Set'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-get-vmcontext:1] Set("SIP/Proxy_ESN-00000000", "VMCONTEXT=default") in new stack
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: Set
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Expression result is '0'
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'GotoIf'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-get-vmcontext:2] GotoIf("SIP/Proxy_ESN-00000000", "0?200:300") in new stack
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Goto (macro-get-vmcontext,s,300)
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: GotoIf
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'NoOp'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s@macro-get-vmcontext:300] NoOp("SIP/Proxy_ESN-00000000", "") in new stack
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: NoOp
[Jul 30 13:56:45] DEBUG[21534] app_macro.c: Executed application: Macro
[Jul 30 13:56:45] DEBUG[21534] pbx.c: Launching 'VoiceMail'
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- Executing [s-CHANUNAVAIL@macro-vm:2] VoiceMail("SIP/Proxy_ESN-00000000", "9999@default,u""") in new stack
[Jul 30 13:56:45] DEBUG[21534] chan_sip.c: SIP answering channel: SIP/Proxy_ESN-00000000
[Jul 30 13:56:45] DEBUG[21534] chan_sip.c: Setting framing from config on incoming call
[Jul 30 13:56:45] DEBUG[21534] chan_sip.c: ** Our capability: 0x28000c (ulaw|alaw|h263|h264) Video flag: False Text flag: True
[Jul 30 13:56:45] DEBUG[21534] chan_sip.c: ** Our prefcodec: 0x0 (nothing) 
[Jul 30 13:56:45] DEBUG[21534] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 156.150.133.165:5060
[Jul 30 13:56:45] DEBUG[21500] chan_sip.c: Stopping retransmission on '7bcedf89276171fc6abfb467787093e8@156.150.133.165' of Response 102: Match Found
[Jul 30 13:56:45] DEBUG[21534] chan_sip.c: Oooh, format changed to 8 alaw
[Jul 30 13:56:45] DEBUG[21534] channel.c: Set channel SIP/Proxy_ESN-00000000 to read format ulaw
[Jul 30 13:56:45] DEBUG[21534] channel.c: Set channel SIP/Proxy_ESN-00000000 to write format ulaw
[Jul 30 13:56:45] DEBUG[21534] app_voicemail.c: /var/spool/asterisk/voicemail/default/9999/unavail doesn't exist, doing what we can
[Jul 30 13:56:45] DEBUG[21534] channel.c: Set channel SIP/Proxy_ESN-00000000 to write format slin
[Jul 30 13:56:45] DEBUG[21534] rtp.c: Ooh, format changed from unknown to alaw
[Jul 30 13:56:45] DEBUG[21534] rtp.c: Created smoother: format: 8 ms: 20 len: 160
[Jul 30 13:56:45] VERBOSE[21534] logger.c:     -- <SIP/Proxy_ESN-00000000> Playing 'vm-theperson.slin' (language 'de')
[Jul 30 13:56:45] NOTICE[21534] channel.c: Dropping incompatible voice frame on SIP/Proxy_ESN-00000000 of format ulaw since our native format has changed to 0x280008 (alaw|h263|h264)
[Jul 30 13:56:47] DEBUG[21534] channel.c: Set channel SIP/Proxy_ESN-00000000 to write format ulaw
[Jul 30 13:56:47] DEBUG[21534] channel.c: Set channel SIP/Proxy_ESN-00000000 to write format slin
[Jul 30 13:56:47] VERBOSE[21534] logger.c:     -- <SIP/Proxy_ESN-00000000> Playing 'digits/9.slin' (language 'de')
[Jul 30 13:56:47] DEBUG[21534] channel.c: Set channel SIP/Proxy_ESN-00000000 to write format ulaw
[Jul 30 13:56:47] DEBUG[21534] channel.c: Set channel SIP/Proxy_ESN-00000000 to write format slin
[Jul 30 13:56:47] VERBOSE[21534] logger.c:     -- <SIP/Proxy_ESN-00000000> Playing 'digits/9.slin' (language 'de')
[Jul 30 13:56:48] DEBUG[21534] channel.c: Set channel SIP/Proxy_ESN-00000000 to write format ulaw
[Jul 30 13:56:48] DEBUG[21534] channel.c: Set channel SIP/Proxy_ESN-00000000 to write format slin
[Jul 30 13:56:48] VERBOSE[21534] logger.c:     -- <SIP/Proxy_ESN-00000000> Playing 'digits/9.slin' (language 'de')
[Jul 30 13:56:48] DEBUG[21520] manager.c: Manager received command 'Command'
[Jul 30 13:56:48] DEBUG[21520] manager.c: Manager received command 'Command'
[Jul 30 13:56:48] DEBUG[21520] manager.c: Manager received command 'Command'
[Jul 30 13:56:48] DEBUG[21520] manager.c: Manager received command 'MailboxStatus'
[Jul 30 13:56:48] WARNING[21520] app_voicemail.c: IMAP Warning: Unknown message data: 1 EXPUNGE
[Jul 30 13:56:48] DEBUG[21520] app_voicemail.c: IMAP Info: Reusing connection to 156.150.130.20/user="A100670@deuser.de.intra\A100658"
[Jul 30 13:56:48] DEBUG[21520] app_voicemail.c: IMAP Info: Mailbox is empty
[Jul 30 13:56:49] DEBUG[21520] manager.c: Manager received command 'MailboxCount'
[Jul 30 13:56:49] DEBUG[21520] app_voicemail.c: IMAP Info: Reusing connection to 156.150.130.20/user="A100670@deuser.de.intra\A100658"
[Jul 30 13:56:49] DEBUG[21520] app_voicemail.c: IMAP Info: Mailbox is empty
[Jul 30 13:56:49] DEBUG[21520] app_voicemail.c: IMAP Info: Reusing connection to 156.150.130.20/user="A100670@deuser.de.intra\A100658"
[Jul 30 13:56:49] DEBUG[21520] app_voicemail.c: IMAP Info: Mailbox is empty
[Jul 30 13:56:49] DEBUG[21534] channel.c: Set channel SIP/Proxy_ESN-00000000 to write format ulaw
[Jul 30 13:56:49] DEBUG[21534] channel.c: Set channel SIP/Proxy_ESN-00000000 to write format slin
[Jul 30 13:56:49] VERBOSE[21534] logger.c:     -- <SIP/Proxy_ESN-00000000> Playing 'digits/9.slin' (language 'de')
[Jul 30 13:56:50] DEBUG[21534] channel.c: Set channel SIP/Proxy_ESN-00000000 to write format ulaw
[Jul 30 13:56:50] DEBUG[21534] channel.c: Set channel SIP/Proxy_ESN-00000000 to write format slin
[Jul 30 13:56:50] VERBOSE[21534] logger.c:     -- <SIP/Proxy_ESN-00000000> Playing 'vm-isunavail.slin' (language 'de')
[Jul 30 13:56:51] DEBUG[21534] channel.c: Set channel SIP/Proxy_ESN-00000000 to write format ulaw
[Jul 30 13:56:51] DEBUG[21534] channel.c: Set channel SIP/Proxy_ESN-00000000 to write format slin
[Jul 30 13:56:51] VERBOSE[21534] logger.c:     -- <SIP/Proxy_ESN-00000000> Playing 'vm-intro.slin' (language 'de')
[Jul 30 13:56:56] DEBUG[21534] channel.c: Set channel SIP/Proxy_ESN-00000000 to write format ulaw
[Jul 30 13:56:56] DEBUG[21534] app_voicemail.c: IMAP Info: Reusing connection to 156.150.130.20/user="A100670@deuser.de.intra\A100658"
[Jul 30 13:56:56] DEBUG[21534] app_voicemail.c: IMAP Info: Mailbox is empty
[Jul 30 13:56:56] DEBUG[21534] app_voicemail.c: IMAP Info: Reusing connection to 156.150.130.20/user="A100670@deuser.de.intra\A100658"
[Jul 30 13:56:56] DEBUG[21534] app_voicemail.c: IMAP Info: Mailbox is empty
[Jul 30 13:56:56] ERROR[21534] app_voicemail.c: IMAP Error: Quota not available on this IMAP server
[Jul 30 13:56:56] DEBUG[21534] channel.c: Set channel SIP/Proxy_ESN-00000000 to write format slin
[Jul 30 13:56:56] VERBOSE[21534] logger.c:     -- <SIP/Proxy_ESN-00000000> Playing 'beep.slin' (language 'de')
[Jul 30 13:56:57] DEBUG[21534] channel.c: Set channel SIP/Proxy_ESN-00000000 to write format ulaw
[Jul 30 13:56:57] VERBOSE[21534] logger.c:     -- Recording the message
[Jul 30 13:56:57] DEBUG[21534] app.c: play_and_record: <None>, /var/spool/asterisk/voicemail/default/9999/tmp/0Sl1Xp, 'wav49|gsm|wav'
[Jul 30 13:56:57] DEBUG[21534] app.c: Recording Formats: sfmts=wav49
[Jul 30 13:56:57] VERBOSE[21534] logger.c:     -- x=0, open writing:  /var/spool/asterisk/voicemail/default/9999/tmp/0Sl1Xp format: wav49, 0x855ff10
[Jul 30 13:56:57] VERBOSE[21534] logger.c:     -- x=1, open writing:  /var/spool/asterisk/voicemail/default/9999/tmp/0Sl1Xp format: gsm, 0x8570a10
[Jul 30 13:56:57] VERBOSE[21534] logger.c:     -- x=2, open writing:  /var/spool/asterisk/voicemail/default/9999/tmp/0Sl1Xp format: wav, 0x84cf590
[Jul 30 13:56:57] DEBUG[21534] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[Jul 30 13:56:57] DEBUG[21534] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[Jul 30 13:56:57] DEBUG[21534] channel.c: Set channel SIP/Proxy_ESN-00000000 to read format slin
[Jul 30 13:56:57] DEBUG[21534] chan_sip.c: Trying to put 'INFO sip:00' onto UDP socket destined for 156.150.133.165:5060
[Jul 30 13:56:57] DEBUG[21500] chan_sip.c: Stopping retransmission on '7bcedf89276171fc6abfb467787093e8@156.150.133.165' of Request 102: Match Found
[Jul 30 13:57:03] DEBUG[21500] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 156.150.133.165:5060
[Jul 30 13:57:03] VERBOSE[21534] logger.c:     -- User hung up
[Jul 30 13:57:03] DEBUG[21534] channel.c: Set channel SIP/Proxy_ESN-00000000 to read format ulaw
[Jul 30 13:57:03] DEBUG[21534] app.c: Locked path '/var/spool/asterisk/voicemail/default/9999/INBOX'
[Jul 30 13:57:03] DEBUG[21534] app.c: Unlocked path '/var/spool/asterisk/voicemail/default/9999/INBOX'
[Jul 30 13:57:03] DEBUG[21534] app_voicemail.c: IMAP Info: Reusing connection to 156.150.130.20/user="A100670@deuser.de.intra\A100658"
[Jul 30 13:57:03] DEBUG[21534] app_voicemail.c: IMAP Info: Mailbox is empty
[Jul 30 13:57:03] DEBUG[21534] app_voicemail.c: IMAP Info: Reusing connection to 156.150.130.20/user="A100670@deuser.de.intra\A100658"
[Jul 30 13:57:04] DEBUG[21534] app_voicemail.c: IMAP Info: Mailbox is empty
[Jul 30 13:57:04] ERROR[21534] app_voicemail.c: IMAP Error: Quota not available on this IMAP server
[Jul 30 13:57:04] DEBUG[21534] app_voicemail.c: IMAP Info: Reusing connection to 156.150.130.20/user="A100670@deuser.de.intra\A100658"
[Jul 30 13:57:04] DEBUG[21534] app_voicemail.c: IMAP Info: Mailbox is empty
[Jul 30 13:57:04] DEBUG[21534] app_voicemail.c: IMAP Info: [APPENDUID 430865 3] APPEND completed.
[Jul 30 13:57:04] DEBUG[21534] app_voicemail.c: IMAP Info: Reusing connection to 156.150.130.20/user="A100670@deuser.de.intra\A100658"
[Jul 30 13:57:04] DEBUG[21534] app_voicemail.c: IMAP Info: [UNSEEN 1] Is the first unseen message
[Jul 30 13:57:04] DEBUG[21534] app_voicemail.c: IMAP Info: Reusing connection to 156.150.130.20/user="A100670@deuser.de.intra\A100658"
[Jul 30 13:57:04] DEBUG[21534] app_voicemail.c: IMAP Info: [UNSEEN 1] Is the first unseen message
[Jul 30 13:57:04] DEBUG[21534] app_voicemail.c: IMAP Info: Reusing connection to 156.150.130.20/user="A100670@deuser.de.intra\A100658"
[Jul 30 13:57:04] DEBUG[21534] app_voicemail.c: IMAP Info: [UNSEEN 1] Is the first unseen message
[Jul 30 13:57:04] DEBUG[21534] app_voicemail.c: IMAP Info: Reusing connection to 156.150.130.20/user="A100670@deuser.de.intra\A100658"
[Jul 30 13:57:04] DEBUG[21534] app_voicemail.c: IMAP Info: [UNSEEN 1] Is the first unseen message
[Jul 30 13:57:04] VERBOSE[21534] logger.c:   == Spawn extension (macro-vm, s-CHANUNAVAIL, 2) exited non-zero on 'SIP/Proxy_ESN-00000000' in macro 'vm'
[Jul 30 13:57:04] VERBOSE[21534] logger.c:   == Spawn extension (macro-exten-vm, s, 18) exited non-zero on 'SIP/Proxy_ESN-00000000' in macro 'exten-vm'
[Jul 30 13:57:04] DEBUG[21534] pbx.c: Spawn extension (from-internal,9999,1) exited non-zero on 'SIP/Proxy_ESN-00000000'
[Jul 30 13:57:04] VERBOSE[21534] logger.c:   == Spawn extension (from-internal, 9999, 1) exited non-zero on 'SIP/Proxy_ESN-00000000'
[Jul 30 13:57:04] DEBUG[21534] channel.c: Soft-Hanging up channel 'SIP/Proxy_ESN-00000000'
[Jul 30 13:57:04] DEBUG[21534] pbx.c: Launching 'Macro'
[Jul 30 13:57:04] VERBOSE[21534] logger.c:     -- Executing [h@from-internal:1] Macro("SIP/Proxy_ESN-00000000", "hangupcall") in new stack
[Jul 30 13:57:04] DEBUG[21534] pbx.c: Expression result is '1'
[Jul 30 13:57:04] DEBUG[21534] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:04] VERBOSE[21534] logger.c:     -- Executing [s@macro-hangupcall:1] GotoIf("SIP/Proxy_ESN-00000000", "1?skiprg") in new stack
[Jul 30 13:57:04] VERBOSE[21534] logger.c:     -- Goto (macro-hangupcall,s,4)
[Jul 30 13:57:04] DEBUG[21534] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:04] DEBUG[21534] pbx.c: Expression result is '1'
[Jul 30 13:57:04] DEBUG[21534] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:04] VERBOSE[21534] logger.c:     -- Executing [s@macro-hangupcall:4] GotoIf("SIP/Proxy_ESN-00000000", "1?skipblkvm") in new stack
[Jul 30 13:57:04] VERBOSE[21534] logger.c:     -- Goto (macro-hangupcall,s,7)
[Jul 30 13:57:04] DEBUG[21534] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:04] DEBUG[21534] pbx.c: Expression result is '1'
[Jul 30 13:57:04] DEBUG[21534] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:04] VERBOSE[21534] logger.c:     -- Executing [s@macro-hangupcall:7] GotoIf("SIP/Proxy_ESN-00000000", "1?theend") in new stack
[Jul 30 13:57:04] VERBOSE[21534] logger.c:     -- Goto (macro-hangupcall,s,9)
[Jul 30 13:57:04] DEBUG[21534] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:04] DEBUG[21534] pbx.c: Launching 'Hangup'
[Jul 30 13:57:04] VERBOSE[21534] logger.c:     -- Executing [s@macro-hangupcall:9] Hangup("SIP/Proxy_ESN-00000000", "") in new stack
[Jul 30 13:57:04] VERBOSE[21534] logger.c:   == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'SIP/Proxy_ESN-00000000' in macro 'hangupcall'
[Jul 30 13:57:04] DEBUG[21534] pbx.c: Spawn extension (from-internal,h,1) exited non-zero on 'SIP/Proxy_ESN-00000000'
[Jul 30 13:57:04] VERBOSE[21534] logger.c:   == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/Proxy_ESN-00000000'
[Jul 30 13:57:04] DEBUG[21534] channel.c: Hanging up channel 'SIP/Proxy_ESN-00000000'
[Jul 30 13:57:04] DEBUG[21534] chan_sip.c: Hangup call SIP/Proxy_ESN-00000000, SIP callid 7bcedf89276171fc6abfb467787093e8@156.150.133.165
[Jul 30 13:57:13] VERBOSE[21500] logger.c:   == Using SIP RTP TOS bits 184
[Jul 30 13:57:13] VERBOSE[21500] logger.c:   == Using SIP RTP CoS mark 5
[Jul 30 13:57:13] VERBOSE[21500] logger.c:   == Using SIP VRTP TOS bits 136
[Jul 30 13:57:13] VERBOSE[21500] logger.c:   == Using SIP VRTP CoS mark 6
[Jul 30 13:57:13] DEBUG[21500] chan_sip.c: Setting NAT on RTP to Off
[Jul 30 13:57:13] DEBUG[21500] chan_sip.c: Setting NAT on VRTP to Off
[Jul 30 13:57:13] DEBUG[21500] chan_sip.c: Allocating new SIP dialog for 56e35e8f41db49a53be315293f934564@156.150.133.165 - INVITE (With RTP)
[Jul 30 13:57:13] DEBUG[21500] chan_sip.c: Setting NAT on RTP to Off
[Jul 30 13:57:13] DEBUG[21500] chan_sip.c: Setting NAT on VRTP to Off
[Jul 30 13:57:13] DEBUG[21500] chan_sip.c: Checking SIP call limits for device esn
[Jul 30 13:57:13] DEBUG[21500] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 156.150.133.165:5060
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'Macro'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [9999@from-internal:1] Macro("SIP/Proxy_ESN-00000001", "exten-vm,9999,9999") in new stack
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'Macro'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-exten-vm:1] Macro("SIP/Proxy_ESN-00000001", "user-callerid") in new stack
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '1'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Function result is '008029'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Function result is '008029'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'Set'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-user-callerid:1] Set("SIP/Proxy_ESN-00000001", "AMPUSER=008029") in new stack
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: Set
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '0'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-user-callerid:2] GotoIf("SIP/Proxy_ESN-00000001", "0?report") in new stack
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Not taking any branch
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '1'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Function result is '008029'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'ExecIf'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-user-callerid:3] ExecIf("SIP/Proxy_ESN-00000001", "1?Set(REALCALLERIDNUM=008029)") in new stack
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: ExecIf
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '0'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Function result is '008029'
[Jul 30 13:57:13] DEBUG[21537] db.c: Unable to find key '008029/user' in family 'DEVICE'
[Jul 30 13:57:13] DEBUG[21537] func_db.c: DB: DEVICE/008029/user not found in database.
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Function result is ''
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'Set'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-user-callerid:4] Set("SIP/Proxy_ESN-00000001", "AMPUSER=") in new stack
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: Set
[Jul 30 13:57:13] DEBUG[21537] db.c: Unable to find key '/cidname' in family 'AMPUSER'
[Jul 30 13:57:13] DEBUG[21537] func_db.c: DB: AMPUSER//cidname not found in database.
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Function result is ''
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'Set'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-user-callerid:5] Set("SIP/Proxy_ESN-00000001", "AMPUSERCIDNAME=") in new stack
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: Set
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '1'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-user-callerid:6] GotoIf("SIP/Proxy_ESN-00000001", "1?report") in new stack
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Goto (macro-user-callerid,s,10)
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '0'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-user-callerid:10] GotoIf("SIP/Proxy_ESN-00000001", "0?continue") in new stack
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Not taking any branch
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '1'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '-1'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Function result is '64'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'Set'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-user-callerid:11] Set("SIP/Proxy_ESN-00000001", "__TTL=64") in new stack
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: Set
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '1'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-user-callerid:12] GotoIf("SIP/Proxy_ESN-00000001", "1?continue") in new stack
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Goto (macro-user-callerid,s,19)
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Function result is '"GUTZKE KLAUS" <008029>'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'NoOp'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-user-callerid:19] NoOp("SIP/Proxy_ESN-00000001", "Using CallerID "GUTZKE KLAUS" <008029>") in new stack
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: Noop
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: Macro
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'Set'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-exten-vm:2] Set("SIP/Proxy_ESN-00000001", "RingGroupMethod=none") in new stack
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: Set
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'Set'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-exten-vm:3] Set("SIP/Proxy_ESN-00000001", "VMBOX=9999") in new stack
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: Set
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'Set'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-exten-vm:4] Set("SIP/Proxy_ESN-00000001", "EXTTOCALL=9999") in new stack
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: Set
[Jul 30 13:57:13] DEBUG[21537] db.c: Unable to find key '9999' in family 'CFU'
[Jul 30 13:57:13] DEBUG[21537] func_db.c: DB: CFU/9999 not found in database.
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Function result is ''
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'Set'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-exten-vm:5] Set("SIP/Proxy_ESN-00000001", "CFUEXT=") in new stack
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: Set
[Jul 30 13:57:13] DEBUG[21537] db.c: Unable to find key '9999' in family 'CFB'
[Jul 30 13:57:13] DEBUG[21537] func_db.c: DB: CFB/9999 not found in database.
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Function result is ''
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'Set'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-exten-vm:6] Set("SIP/Proxy_ESN-00000001", "CFBEXT=") in new stack
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: Set
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '1'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '0'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '1'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Function result is '15'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'Set'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-exten-vm:7] Set("SIP/Proxy_ESN-00000001", "RT=15") in new stack
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: Set
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'Macro'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-exten-vm:8] Macro("SIP/Proxy_ESN-00000001", "record-enable,9999,IN") in new stack
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '1'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-record-enable:1] GotoIf("SIP/Proxy_ESN-00000001", "1?check") in new stack
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Goto (macro-record-enable,s,4)
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Function result is '20100730-135713'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'AGI'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-record-enable:4] AGI("SIP/Proxy_ESN-00000001", "recordingcheck,20100730-135713,1280491033.1") in new stack
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
[Jul 30 13:57:13] VERBOSE[21537] logger.c:  recordingcheck,20100730-135713,1280491033.1: Inbound recording not enabled
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- <SIP/Proxy_ESN-00000001>AGI Script recordingcheck completed, returning 0
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: AGI
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'MacroExit'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-record-enable:5] MacroExit("SIP/Proxy_ESN-00000001", "") in new stack
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: Macro
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'Macro'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-exten-vm:9] Macro("SIP/Proxy_ESN-00000001", "dial,15,tr,9999") in new stack
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '1'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-dial:1] GotoIf("SIP/Proxy_ESN-00000001", "1?dial") in new stack
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Goto (macro-dial,s,3)
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'AGI'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-dial:3] AGI("SIP/Proxy_ESN-00000001", "dialparties.agi") in new stack
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
[Jul 30 13:57:13] DEBUG[21500] chan_sip.c: Allocating new SIP dialog for 3462daae1e47647473cdf8757eeb832b@156.150.133.165 - OPTIONS (No RTP)
[Jul 30 13:57:13] DEBUG[21500] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 156.150.133.165:5060
[Jul 30 13:57:13] VERBOSE[21537] logger.c:  dialparties.agi: Starting New Dialparties.agi
[Jul 30 13:57:13] VERBOSE[21537] logger.c:  dialparties.agi: Caller ID name is 'GUTZKE KLAUS' number is '008029'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:        > dialparties.agi: USE_CONFIRMATION:  'FALSE'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:        > dialparties.agi: RINGGROUP_INDEX:   ''
[Jul 30 13:57:13] VERBOSE[21537] logger.c:  dialparties.agi: Methodology of ring is  'none'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- dialparties.agi: Added extension 9999 to extension map
[Jul 30 13:57:13] DEBUG[21537] db.c: Unable to find key '9999' in family 'CF'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- dialparties.agi: Extension 9999 cf is disabled
[Jul 30 13:57:13] DEBUG[21537] db.c: Unable to find key '9999' in family 'DND'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- dialparties.agi: Extension 9999 do not disturb is disabled
[Jul 30 13:57:13] DEBUG[21537] db.c: Unable to find key '9999' in family 'CFB'
[Jul 30 13:57:13] DEBUG[21537] db.c: Unable to find key '9999' in family 'CFU'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:        > dialparties.agi: extnum 9999 has:  cw: 1; hascfb: 0 [] hascfu: 0 []
[Jul 30 13:57:13] DEBUG[21537] db.c: Unable to find key 'DND9999' in family 'CustomDevstate'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:  dialparties.agi: EXTENSION_STATE: 4 (UNAVAILABLE)
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- dialparties.agi: dbset CALLTRACE/9999 to 008029
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- dialparties.agi: Filtered ARG3: 9999
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- <SIP/Proxy_ESN-00000001>AGI Script dialparties.agi completed, returning 0
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: AGI
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'Dial'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-dial:7] Dial("SIP/Proxy_ESN-00000001", "SIP/9999,15,tr") in new stack
[Jul 30 13:57:13] DEBUG[21537] chan_sip.c: Asked to create a SIP channel with formats: 0x280004 (ulaw|h263|h264)
[Jul 30 13:57:13] VERBOSE[21537] logger.c:   == Using SIP RTP TOS bits 184
[Jul 30 13:57:13] VERBOSE[21537] logger.c:   == Using SIP RTP CoS mark 5
[Jul 30 13:57:13] VERBOSE[21537] logger.c:   == Using SIP VRTP TOS bits 136
[Jul 30 13:57:13] VERBOSE[21537] logger.c:   == Using SIP VRTP CoS mark 6
[Jul 30 13:57:13] DEBUG[21537] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
[Jul 30 13:57:13] WARNING[21537] app_dial.c: Unable to create channel of type 'SIP' (cause 20 - Unknown)
[Jul 30 13:57:13] VERBOSE[21537] logger.c:   == Everyone is busy/congested at this time (1:0/0/1)
[Jul 30 13:57:13] DEBUG[21537] rtp.c: Channel '<unspecified>' has no RTP, not doing anything
[Jul 30 13:57:13] DEBUG[21537] app_dial.c: Exiting with DIALSTATUS=CHANUNAVAIL.
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: Dial
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '0'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Function result is 'CHANUNAVAIL'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'Set'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-dial:8] Set("SIP/Proxy_ESN-00000001", "DIALSTATUS=CHANUNAVAIL") in new stack
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: Set
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '0'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'GosubIf'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-dial:9] GosubIf("SIP/Proxy_ESN-00000001", "0?CHANUNAVAIL,1") in new stack
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: GosubIf
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '0'
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: Macro
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '1'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '0'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '0'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '0'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-exten-vm:10] GotoIf("SIP/Proxy_ESN-00000001", "0?exit,return") in new stack
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Not taking any branch
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'Set'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-exten-vm:11] Set("SIP/Proxy_ESN-00000001", "SV_DIALSTATUS=CHANUNAVAIL") in new stack
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: Set
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '0'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '0'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '1'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '0'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'GosubIf'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-exten-vm:12] GosubIf("SIP/Proxy_ESN-00000001", "0?docfu,1") in new stack
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: GosubIf
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '0'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '0'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '1'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '0'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '0'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '0'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '0'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'GosubIf'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-exten-vm:13] GosubIf("SIP/Proxy_ESN-00000001", "0?docfb,1") in new stack
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: GosubIf
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '0'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '0'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '0'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'Set'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-exten-vm:14] Set("SIP/Proxy_ESN-00000001", "DIALSTATUS=CHANUNAVAIL") in new stack
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: Set
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'NoOp'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-exten-vm:15] NoOp("SIP/Proxy_ESN-00000001", "Voicemail is '9999'") in new stack
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: NoOp
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '0'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-exten-vm:16] GotoIf("SIP/Proxy_ESN-00000001", "0?s-CHANUNAVAIL,1") in new stack
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Not taking any branch
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'NoOp'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-exten-vm:17] NoOp("SIP/Proxy_ESN-00000001", "Sending to Voicemail box 9999") in new stack
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: NoOp
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'Macro'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-exten-vm:18] Macro("SIP/Proxy_ESN-00000001", "vm,9999,CHANUNAVAIL,") in new stack
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'Macro'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-vm:1] Macro("SIP/Proxy_ESN-00000001", "user-callerid,SKIPTTL") in new stack
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '1'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Function result is '008029'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Function result is '008029'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'Set'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-user-callerid:1] Set("SIP/Proxy_ESN-00000001", "AMPUSER=008029") in new stack
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: Set
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '0'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-user-callerid:2] GotoIf("SIP/Proxy_ESN-00000001", "0?report") in new stack
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Not taking any branch
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '0'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Function result is '008029'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'ExecIf'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-user-callerid:3] ExecIf("SIP/Proxy_ESN-00000001", "0?Set(REALCALLERIDNUM=008029)") in new stack
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: ExecIf
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '0'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Function result is '008029'
[Jul 30 13:57:13] DEBUG[21537] db.c: Unable to find key '008029/user' in family 'DEVICE'
[Jul 30 13:57:13] DEBUG[21537] func_db.c: DB: DEVICE/008029/user not found in database.
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Function result is ''
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'Set'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-user-callerid:4] Set("SIP/Proxy_ESN-00000001", "AMPUSER=") in new stack
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: Set
[Jul 30 13:57:13] DEBUG[21537] db.c: Unable to find key '/cidname' in family 'AMPUSER'
[Jul 30 13:57:13] DEBUG[21537] func_db.c: DB: AMPUSER//cidname not found in database.
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Function result is ''
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'Set'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-user-callerid:5] Set("SIP/Proxy_ESN-00000001", "AMPUSERCIDNAME=") in new stack
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: Set
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '1'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-user-callerid:6] GotoIf("SIP/Proxy_ESN-00000001", "1?report") in new stack
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Goto (macro-user-callerid,s,10)
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '1'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-user-callerid:10] GotoIf("SIP/Proxy_ESN-00000001", "1?continue") in new stack
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Goto (macro-user-callerid,s,19)
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Function result is '"GUTZKE KLAUS" <008029>'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'NoOp'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-user-callerid:19] NoOp("SIP/Proxy_ESN-00000001", "Using CallerID "GUTZKE KLAUS" <008029>") in new stack
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: Noop
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: Macro
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '0'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Function result is '""'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'Set'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-vm:2] Set("SIP/Proxy_ESN-00000001", "VMGAIN=""") in new stack
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: Set
[Jul 30 13:57:13] WARNING[21537] func_db.c: DB requires an argument, DB(<family>/<key>)
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Function result is '(null)'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '1'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-vm:3] GotoIf("SIP/Proxy_ESN-00000001", "1?vmx,1") in new stack
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Goto (macro-vm,vmx,1)
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '0'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [vmx@macro-vm:1] GotoIf("SIP/Proxy_ESN-00000001", "0?s-CHANUNAVAIL,1") in new stack
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Not taking any branch
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '0'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Function result is 'unavail'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'Set'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [vmx@macro-vm:2] Set("SIP/Proxy_ESN-00000001", "MODE=unavail") in new stack
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: Set
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '1'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [vmx@macro-vm:3] GotoIf("SIP/Proxy_ESN-00000001", "1?notdirect") in new stack
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Goto (macro-vm,vmx,5)
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:13] DEBUG[21537] db.c: Unable to find key '9999/vmx/unavail/state' in family 'AMPUSER'
[Jul 30 13:57:13] DEBUG[21537] func_db.c: DB: AMPUSER/9999/vmx/unavail/state not found in database.
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Function result is ''
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'NoOp'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [vmx@macro-vm:5] NoOp("SIP/Proxy_ESN-00000001", "Checking if ext 9999 is enabled: ") in new stack
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: Noop
[Jul 30 13:57:13] DEBUG[21537] db.c: Unable to find key '9999/vmx/unavail/state' in family 'AMPUSER'
[Jul 30 13:57:13] DEBUG[21537] func_db.c: DB: AMPUSER/9999/vmx/unavail/state not found in database.
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Function result is ''
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '1'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [vmx@macro-vm:6] GotoIf("SIP/Proxy_ESN-00000001", "1?s-CHANUNAVAIL,1") in new stack
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Goto (macro-vm,s-CHANUNAVAIL,1)
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'Macro'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s-CHANUNAVAIL@macro-vm:1] Macro("SIP/Proxy_ESN-00000001", "get-vmcontext,9999") in new stack
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Function result is 'default'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'Set'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-get-vmcontext:1] Set("SIP/Proxy_ESN-00000001", "VMCONTEXT=default") in new stack
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: Set
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Expression result is '0'
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-get-vmcontext:2] GotoIf("SIP/Proxy_ESN-00000001", "0?200:300") in new stack
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Goto (macro-get-vmcontext,s,300)
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'NoOp'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s@macro-get-vmcontext:300] NoOp("SIP/Proxy_ESN-00000001", "") in new stack
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: NoOp
[Jul 30 13:57:13] DEBUG[21537] app_macro.c: Executed application: Macro
[Jul 30 13:57:13] DEBUG[21537] pbx.c: Launching 'VoiceMail'
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- Executing [s-CHANUNAVAIL@macro-vm:2] VoiceMail("SIP/Proxy_ESN-00000001", "9999@default,u""") in new stack
[Jul 30 13:57:13] DEBUG[21537] chan_sip.c: SIP answering channel: SIP/Proxy_ESN-00000001
[Jul 30 13:57:13] DEBUG[21537] chan_sip.c: Setting framing from config on incoming call
[Jul 30 13:57:13] DEBUG[21537] chan_sip.c: ** Our capability: 0x28000c (ulaw|alaw|h263|h264) Video flag: False Text flag: True
[Jul 30 13:57:13] DEBUG[21537] chan_sip.c: ** Our prefcodec: 0x0 (nothing) 
[Jul 30 13:57:13] DEBUG[21537] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 156.150.133.165:5060
[Jul 30 13:57:13] DEBUG[21500] chan_sip.c: Stopping retransmission on '56e35e8f41db49a53be315293f934564@156.150.133.165' of Response 102: Match Found
[Jul 30 13:57:13] DEBUG[21537] chan_sip.c: Oooh, format changed to 8 alaw
[Jul 30 13:57:13] DEBUG[21537] channel.c: Set channel SIP/Proxy_ESN-00000001 to read format ulaw
[Jul 30 13:57:13] DEBUG[21537] channel.c: Set channel SIP/Proxy_ESN-00000001 to write format ulaw
[Jul 30 13:57:13] DEBUG[21537] app_voicemail.c: /var/spool/asterisk/voicemail/default/9999/unavail doesn't exist, doing what we can
[Jul 30 13:57:13] DEBUG[21537] channel.c: Set channel SIP/Proxy_ESN-00000001 to write format slin
[Jul 30 13:57:13] DEBUG[21537] rtp.c: Ooh, format changed from unknown to alaw
[Jul 30 13:57:13] DEBUG[21537] rtp.c: Created smoother: format: 8 ms: 20 len: 160
[Jul 30 13:57:13] VERBOSE[21537] logger.c:     -- <SIP/Proxy_ESN-00000001> Playing 'vm-theperson.slin' (language 'de')
[Jul 30 13:57:13] NOTICE[21537] channel.c: Dropping incompatible voice frame on SIP/Proxy_ESN-00000001 of format ulaw since our native format has changed to 0x280008 (alaw|h263|h264)
[Jul 30 13:57:14] DEBUG[21537] rtp.c: Sending dtmf: 42 (*), at 156.150.133.165
[Jul 30 13:57:14] DEBUG[21537] channel.c: Set channel SIP/Proxy_ESN-00000001 to write format ulaw
[Jul 30 13:57:14] DEBUG[21537] channel.c: Set channel SIP/Proxy_ESN-00000001 to write format slin
[Jul 30 13:57:14] VERBOSE[21537] logger.c:     -- <SIP/Proxy_ESN-00000001> Playing 'digits/9.slin' (language 'de')
[Jul 30 13:57:15] DEBUG[21537] rtp.c: Sending dtmf: 42 (*), at 156.150.133.165
[Jul 30 13:57:15] DEBUG[21537] channel.c: Set channel SIP/Proxy_ESN-00000001 to write format ulaw
[Jul 30 13:57:15] DEBUG[21537] app_macro.c: Executed application: VoiceMail
[Jul 30 13:57:15] DEBUG[21537] pbx.c: Launching 'Macro'
[Jul 30 13:57:15] VERBOSE[21537] logger.c:     -- Executing [a@macro-vm:1] Macro("SIP/Proxy_ESN-00000001", "get-vmcontext,9999") in new stack
[Jul 30 13:57:15] DEBUG[21537] pbx.c: Function result is 'default'
[Jul 30 13:57:15] DEBUG[21537] pbx.c: Launching 'Set'
[Jul 30 13:57:15] VERBOSE[21537] logger.c:     -- Executing [s@macro-get-vmcontext:1] Set("SIP/Proxy_ESN-00000001", "VMCONTEXT=default") in new stack
[Jul 30 13:57:15] DEBUG[21537] app_macro.c: Executed application: Set
[Jul 30 13:57:15] DEBUG[21537] pbx.c: Expression result is '0'
[Jul 30 13:57:15] DEBUG[21537] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:15] VERBOSE[21537] logger.c:     -- Executing [s@macro-get-vmcontext:2] GotoIf("SIP/Proxy_ESN-00000001", "0?200:300") in new stack
[Jul 30 13:57:15] VERBOSE[21537] logger.c:     -- Goto (macro-get-vmcontext,s,300)
[Jul 30 13:57:15] DEBUG[21537] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:15] DEBUG[21537] pbx.c: Launching 'NoOp'
[Jul 30 13:57:15] VERBOSE[21537] logger.c:     -- Executing [s@macro-get-vmcontext:300] NoOp("SIP/Proxy_ESN-00000001", "") in new stack
[Jul 30 13:57:15] DEBUG[21537] app_macro.c: Executed application: NoOp
[Jul 30 13:57:15] DEBUG[21537] app_macro.c: Executed application: Macro
[Jul 30 13:57:15] DEBUG[21537] db.c: Unable to find key '9999/vmx/unavail/*/ext' in family 'AMPUSER'
[Jul 30 13:57:15] DEBUG[21537] pbx.c: Function result is '0'
[Jul 30 13:57:15] DEBUG[21537] pbx.c: Expression result is '1'
[Jul 30 13:57:15] DEBUG[21537] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:15] VERBOSE[21537] logger.c:     -- Executing [a@macro-vm:2] GotoIf("SIP/Proxy_ESN-00000001", "1?adef,1") in new stack
[Jul 30 13:57:15] VERBOSE[21537] logger.c:     -- Goto (macro-vm,adef,1)
[Jul 30 13:57:15] DEBUG[21537] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:15] DEBUG[21537] pbx.c: Launching 'VoiceMailMain'
[Jul 30 13:57:15] VERBOSE[21537] logger.c:     -- Executing [adef@macro-vm:1] VoiceMailMain("SIP/Proxy_ESN-00000001", "9999@default") in new stack
[Jul 30 13:57:15] DEBUG[21537] app_voicemail.c: Before find user for mailbox 9999
[Jul 30 13:57:15] DEBUG[21537] channel.c: Set channel SIP/Proxy_ESN-00000001 to write format slin
[Jul 30 13:57:15] VERBOSE[21537] logger.c:     -- <SIP/Proxy_ESN-00000001> Playing 'vm-password.slin' (language 'de')
[Jul 30 13:57:16] DEBUG[21537] channel.c: Set channel SIP/Proxy_ESN-00000001 to write format ulaw
[Jul 30 13:57:16] DEBUG[21537] rtp.c: Sending dtmf: 50 (2), at 156.150.133.165
[Jul 30 13:57:16] DEBUG[21537] rtp.c: Sending dtmf: 50 (2), at 156.150.133.165
[Jul 30 13:57:16] DEBUG[21537] rtp.c: Sending dtmf: 48 (0), at 156.150.133.165
[Jul 30 13:57:17] DEBUG[21537] rtp.c: Sending dtmf: 48 (0), at 156.150.133.165
[Jul 30 13:57:17] DEBUG[21537] rtp.c: Sending dtmf: 53 (5), at 156.150.133.165
[Jul 30 13:57:17] DEBUG[21537] rtp.c: Sending dtmf: 53 (5), at 156.150.133.165
[Jul 30 13:57:18] DEBUG[21537] rtp.c: Sending dtmf: 52 (4), at 156.150.133.165
[Jul 30 13:57:18] DEBUG[21537] rtp.c: Sending dtmf: 52 (4), at 156.150.133.165
[Jul 30 13:57:18] DEBUG[21537] rtp.c: Sending dtmf: 35 (#), at 156.150.133.165
[Jul 30 13:57:19] DEBUG[21537] rtp.c: Sending dtmf: 35 (#), at 156.150.133.165
[Jul 30 13:57:19] DEBUG[21537] app_voicemail.c: After vm_authenticate
[Jul 30 13:57:19] DEBUG[21537] app_voicemail.c: Before open_mailbox
[Jul 30 13:57:19] DEBUG[21537] app_voicemail.c: mailstream not set.
[Jul 30 13:57:19] DEBUG[21537] app_voicemail.c: IMAP Info: Trying IP address [156.150.130.20]
[Jul 30 13:57:19] DEBUG[21537] app_voicemail.c: IMAP Info: Microsoft Exchange Server 2003 IMAP4rev1 server version 6.5.7638.1 (DEESX001.deuser.de.intra) ready.
[Jul 30 13:57:19] DEBUG[21537] app_voicemail.c: IMAP Info: [UNSEEN 1] Is the first unseen message
[Jul 30 13:57:19] DEBUG[21537] app_voicemail.c: Number of old messages: 0
[Jul 30 13:57:19] DEBUG[21537] app_voicemail.c: IMAP Info: Reusing connection to 156.150.130.20/user="A100670@deuser.de.intra\A100658"
[Jul 30 13:57:19] DEBUG[21537] app_voicemail.c: IMAP Info: [UNSEEN 1] Is the first unseen message
[Jul 30 13:57:19] ERROR[21537] app_voicemail.c: IMAP Error: Quota not available on this IMAP server
[Jul 30 13:57:19] DEBUG[21537] app_voicemail.c: Number of new messages: 1
[Jul 30 13:57:19] DEBUG[21537] channel.c: Set channel SIP/Proxy_ESN-00000001 to write format slin
[Jul 30 13:57:19] VERBOSE[21537] logger.c:     -- <SIP/Proxy_ESN-00000001> Playing 'vm-youhave.slin' (language 'de')
[Jul 30 13:57:20] DEBUG[21537] channel.c: Set channel SIP/Proxy_ESN-00000001 to write format ulaw
[Jul 30 13:57:20] WARNING[21537] file.c: File digits/1F does not exist in any format
[Jul 30 13:57:20] WARNING[21537] file.c: Unable to open digits/1F (format 0x280008 (alaw|h263|h264)): No such file or directory
[Jul 30 13:57:20] VERBOSE[21537] logger.c:   == Spawn extension (macro-vm, adef, 1) exited non-zero on 'SIP/Proxy_ESN-00000001' in macro 'vm'
[Jul 30 13:57:20] VERBOSE[21537] logger.c:   == Spawn extension (macro-exten-vm, s, 18) exited non-zero on 'SIP/Proxy_ESN-00000001' in macro 'exten-vm'
[Jul 30 13:57:20] DEBUG[21537] pbx.c: Spawn extension (from-internal,9999,1) exited non-zero on 'SIP/Proxy_ESN-00000001'
[Jul 30 13:57:20] VERBOSE[21537] logger.c:   == Spawn extension (from-internal, 9999, 1) exited non-zero on 'SIP/Proxy_ESN-00000001'
[Jul 30 13:57:20] DEBUG[21537] channel.c: Soft-Hanging up channel 'SIP/Proxy_ESN-00000001'
[Jul 30 13:57:20] DEBUG[21537] pbx.c: Launching 'Macro'
[Jul 30 13:57:20] VERBOSE[21537] logger.c:     -- Executing [h@from-internal:1] Macro("SIP/Proxy_ESN-00000001", "hangupcall") in new stack
[Jul 30 13:57:20] DEBUG[21537] pbx.c: Expression result is '1'
[Jul 30 13:57:20] DEBUG[21537] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:20] VERBOSE[21537] logger.c:     -- Executing [s@macro-hangupcall:1] GotoIf("SIP/Proxy_ESN-00000001", "1?skiprg") in new stack
[Jul 30 13:57:20] VERBOSE[21537] logger.c:     -- Goto (macro-hangupcall,s,4)
[Jul 30 13:57:20] DEBUG[21537] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:20] DEBUG[21537] pbx.c: Expression result is '1'
[Jul 30 13:57:20] DEBUG[21537] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:20] VERBOSE[21537] logger.c:     -- Executing [s@macro-hangupcall:4] GotoIf("SIP/Proxy_ESN-00000001", "1?skipblkvm") in new stack
[Jul 30 13:57:20] VERBOSE[21537] logger.c:     -- Goto (macro-hangupcall,s,7)
[Jul 30 13:57:20] DEBUG[21537] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:20] DEBUG[21537] pbx.c: Expression result is '1'
[Jul 30 13:57:20] DEBUG[21537] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:20] VERBOSE[21537] logger.c:     -- Executing [s@macro-hangupcall:7] GotoIf("SIP/Proxy_ESN-00000001", "1?theend") in new stack
[Jul 30 13:57:20] VERBOSE[21537] logger.c:     -- Goto (macro-hangupcall,s,9)
[Jul 30 13:57:20] DEBUG[21537] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:20] DEBUG[21537] pbx.c: Launching 'Hangup'
[Jul 30 13:57:20] VERBOSE[21537] logger.c:     -- Executing [s@macro-hangupcall:9] Hangup("SIP/Proxy_ESN-00000001", "") in new stack
[Jul 30 13:57:20] VERBOSE[21537] logger.c:   == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'SIP/Proxy_ESN-00000001' in macro 'hangupcall'
[Jul 30 13:57:20] DEBUG[21537] pbx.c: Spawn extension (from-internal,h,1) exited non-zero on 'SIP/Proxy_ESN-00000001'
[Jul 30 13:57:20] VERBOSE[21537] logger.c:   == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/Proxy_ESN-00000001'
[Jul 30 13:57:20] DEBUG[21537] channel.c: Hanging up channel 'SIP/Proxy_ESN-00000001'
[Jul 30 13:57:20] DEBUG[21537] chan_sip.c: Hangup call SIP/Proxy_ESN-00000001, SIP callid 56e35e8f41db49a53be315293f934564@156.150.133.165
[Jul 30 13:57:20] DEBUG[21537] chan_sip.c: Trying to put 'BYE sip:008' onto UDP socket destined for 156.150.133.165:5060
[Jul 30 13:57:20] DEBUG[21500] chan_sip.c: Stopping retransmission on '56e35e8f41db49a53be315293f934564@156.150.133.165' of Request 102: Match Found
[Jul 30 13:57:20] DEBUG[21520] manager.c: Manager received command 'MailboxCount'
[Jul 30 13:57:20] DEBUG[21520] app_voicemail.c: IMAP Info: Reusing connection to 156.150.130.20/user="A100670@deuser.de.intra\A100658"
[Jul 30 13:57:20] DEBUG[21520] app_voicemail.c: IMAP Info: [UNSEEN 1] Is the first unseen message
[Jul 30 13:57:20] DEBUG[21520] app_voicemail.c: IMAP Info: Reusing connection to 156.150.130.20/user="A100670@deuser.de.intra\A100658"
[Jul 30 13:57:20] DEBUG[21520] app_voicemail.c: IMAP Info: [UNSEEN 1] Is the first unseen message
[Jul 30 13:57:32] VERBOSE[21500] logger.c:   == Using SIP RTP TOS bits 184
[Jul 30 13:57:32] VERBOSE[21500] logger.c:   == Using SIP RTP CoS mark 5
[Jul 30 13:57:32] VERBOSE[21500] logger.c:   == Using SIP VRTP TOS bits 136
[Jul 30 13:57:32] VERBOSE[21500] logger.c:   == Using SIP VRTP CoS mark 6
[Jul 30 13:57:32] DEBUG[21500] chan_sip.c: Setting NAT on RTP to Off
[Jul 30 13:57:32] DEBUG[21500] chan_sip.c: Setting NAT on VRTP to Off
[Jul 30 13:57:32] DEBUG[21500] chan_sip.c: Allocating new SIP dialog for 2e3bbb290fdd1abf3a09c4083961e09c@156.150.133.165 - INVITE (With RTP)
[Jul 30 13:57:32] DEBUG[21500] chan_sip.c: Setting NAT on RTP to Off
[Jul 30 13:57:32] DEBUG[21500] chan_sip.c: Setting NAT on VRTP to Off
[Jul 30 13:57:32] DEBUG[21500] chan_sip.c: Checking SIP call limits for device esn
[Jul 30 13:57:32] DEBUG[21500] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 156.150.133.165:5060
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'Macro'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [9999@from-internal:1] Macro("SIP/Proxy_ESN-00000002", "exten-vm,9999,9999") in new stack
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'Macro'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-exten-vm:1] Macro("SIP/Proxy_ESN-00000002", "user-callerid") in new stack
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '1'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Function result is '008029'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Function result is '008029'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'Set'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-user-callerid:1] Set("SIP/Proxy_ESN-00000002", "AMPUSER=008029") in new stack
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: Set
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '0'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-user-callerid:2] GotoIf("SIP/Proxy_ESN-00000002", "0?report") in new stack
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Not taking any branch
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '1'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Function result is '008029'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'ExecIf'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-user-callerid:3] ExecIf("SIP/Proxy_ESN-00000002", "1?Set(REALCALLERIDNUM=008029)") in new stack
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: ExecIf
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '0'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Function result is '008029'
[Jul 30 13:57:32] DEBUG[21540] db.c: Unable to find key '008029/user' in family 'DEVICE'
[Jul 30 13:57:32] DEBUG[21540] func_db.c: DB: DEVICE/008029/user not found in database.
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Function result is ''
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'Set'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-user-callerid:4] Set("SIP/Proxy_ESN-00000002", "AMPUSER=") in new stack
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: Set
[Jul 30 13:57:32] DEBUG[21540] db.c: Unable to find key '/cidname' in family 'AMPUSER'
[Jul 30 13:57:32] DEBUG[21540] func_db.c: DB: AMPUSER//cidname not found in database.
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Function result is ''
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'Set'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-user-callerid:5] Set("SIP/Proxy_ESN-00000002", "AMPUSERCIDNAME=") in new stack
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: Set
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '1'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-user-callerid:6] GotoIf("SIP/Proxy_ESN-00000002", "1?report") in new stack
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Goto (macro-user-callerid,s,10)
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '0'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-user-callerid:10] GotoIf("SIP/Proxy_ESN-00000002", "0?continue") in new stack
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Not taking any branch
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '1'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '-1'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Function result is '64'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'Set'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-user-callerid:11] Set("SIP/Proxy_ESN-00000002", "__TTL=64") in new stack
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: Set
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '1'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-user-callerid:12] GotoIf("SIP/Proxy_ESN-00000002", "1?continue") in new stack
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Goto (macro-user-callerid,s,19)
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Function result is '"GUTZKE KLAUS" <008029>'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'NoOp'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-user-callerid:19] NoOp("SIP/Proxy_ESN-00000002", "Using CallerID "GUTZKE KLAUS" <008029>") in new stack
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: Noop
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: Macro
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'Set'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-exten-vm:2] Set("SIP/Proxy_ESN-00000002", "RingGroupMethod=none") in new stack
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: Set
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'Set'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-exten-vm:3] Set("SIP/Proxy_ESN-00000002", "VMBOX=9999") in new stack
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: Set
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'Set'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-exten-vm:4] Set("SIP/Proxy_ESN-00000002", "EXTTOCALL=9999") in new stack
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: Set
[Jul 30 13:57:32] DEBUG[21540] db.c: Unable to find key '9999' in family 'CFU'
[Jul 30 13:57:32] DEBUG[21540] func_db.c: DB: CFU/9999 not found in database.
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Function result is ''
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'Set'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-exten-vm:5] Set("SIP/Proxy_ESN-00000002", "CFUEXT=") in new stack
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: Set
[Jul 30 13:57:32] DEBUG[21540] db.c: Unable to find key '9999' in family 'CFB'
[Jul 30 13:57:32] DEBUG[21540] func_db.c: DB: CFB/9999 not found in database.
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Function result is ''
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'Set'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-exten-vm:6] Set("SIP/Proxy_ESN-00000002", "CFBEXT=") in new stack
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: Set
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '1'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '0'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '1'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Function result is '15'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'Set'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-exten-vm:7] Set("SIP/Proxy_ESN-00000002", "RT=15") in new stack
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: Set
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'Macro'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-exten-vm:8] Macro("SIP/Proxy_ESN-00000002", "record-enable,9999,IN") in new stack
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '1'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-record-enable:1] GotoIf("SIP/Proxy_ESN-00000002", "1?check") in new stack
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Goto (macro-record-enable,s,4)
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Function result is '20100730-135732'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'AGI'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-record-enable:4] AGI("SIP/Proxy_ESN-00000002", "recordingcheck,20100730-135732,1280491052.2") in new stack
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
[Jul 30 13:57:32] VERBOSE[21540] logger.c:  recordingcheck,20100730-135732,1280491052.2: Inbound recording not enabled
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- <SIP/Proxy_ESN-00000002>AGI Script recordingcheck completed, returning 0
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: AGI
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'MacroExit'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-record-enable:5] MacroExit("SIP/Proxy_ESN-00000002", "") in new stack
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: Macro
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'Macro'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-exten-vm:9] Macro("SIP/Proxy_ESN-00000002", "dial,15,tr,9999") in new stack
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '1'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-dial:1] GotoIf("SIP/Proxy_ESN-00000002", "1?dial") in new stack
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Goto (macro-dial,s,3)
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'AGI'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-dial:3] AGI("SIP/Proxy_ESN-00000002", "dialparties.agi") in new stack
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
[Jul 30 13:57:32] VERBOSE[21540] logger.c:  dialparties.agi: Starting New Dialparties.agi
[Jul 30 13:57:32] VERBOSE[21540] logger.c:  dialparties.agi: Caller ID name is 'GUTZKE KLAUS' number is '008029'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:        > dialparties.agi: USE_CONFIRMATION:  'FALSE'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:        > dialparties.agi: RINGGROUP_INDEX:   ''
[Jul 30 13:57:32] VERBOSE[21540] logger.c:  dialparties.agi: Methodology of ring is  'none'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- dialparties.agi: Added extension 9999 to extension map
[Jul 30 13:57:32] DEBUG[21540] db.c: Unable to find key '9999' in family 'CF'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- dialparties.agi: Extension 9999 cf is disabled
[Jul 30 13:57:32] DEBUG[21540] db.c: Unable to find key '9999' in family 'DND'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- dialparties.agi: Extension 9999 do not disturb is disabled
[Jul 30 13:57:32] DEBUG[21540] db.c: Unable to find key '9999' in family 'CFB'
[Jul 30 13:57:32] DEBUG[21540] db.c: Unable to find key '9999' in family 'CFU'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:        > dialparties.agi: extnum 9999 has:  cw: 1; hascfb: 0 [] hascfu: 0 []
[Jul 30 13:57:32] DEBUG[21540] db.c: Unable to find key 'DND9999' in family 'CustomDevstate'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:  dialparties.agi: EXTENSION_STATE: 4 (UNAVAILABLE)
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- dialparties.agi: dbset CALLTRACE/9999 to 008029
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- dialparties.agi: Filtered ARG3: 9999
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- <SIP/Proxy_ESN-00000002>AGI Script dialparties.agi completed, returning 0
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: AGI
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'Dial'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-dial:7] Dial("SIP/Proxy_ESN-00000002", "SIP/9999,15,tr") in new stack
[Jul 30 13:57:32] DEBUG[21540] chan_sip.c: Asked to create a SIP channel with formats: 0x280004 (ulaw|h263|h264)
[Jul 30 13:57:32] VERBOSE[21540] logger.c:   == Using SIP RTP TOS bits 184
[Jul 30 13:57:32] VERBOSE[21540] logger.c:   == Using SIP RTP CoS mark 5
[Jul 30 13:57:32] VERBOSE[21540] logger.c:   == Using SIP VRTP TOS bits 136
[Jul 30 13:57:32] VERBOSE[21540] logger.c:   == Using SIP VRTP CoS mark 6
[Jul 30 13:57:32] DEBUG[21540] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
[Jul 30 13:57:32] WARNING[21540] app_dial.c: Unable to create channel of type 'SIP' (cause 20 - Unknown)
[Jul 30 13:57:32] VERBOSE[21540] logger.c:   == Everyone is busy/congested at this time (1:0/0/1)
[Jul 30 13:57:32] DEBUG[21540] rtp.c: Channel '<unspecified>' has no RTP, not doing anything
[Jul 30 13:57:32] DEBUG[21540] app_dial.c: Exiting with DIALSTATUS=CHANUNAVAIL.
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: Dial
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '0'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Function result is 'CHANUNAVAIL'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'Set'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-dial:8] Set("SIP/Proxy_ESN-00000002", "DIALSTATUS=CHANUNAVAIL") in new stack
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: Set
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '0'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'GosubIf'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-dial:9] GosubIf("SIP/Proxy_ESN-00000002", "0?CHANUNAVAIL,1") in new stack
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: GosubIf
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '0'
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: Macro
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '1'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '0'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '0'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '0'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-exten-vm:10] GotoIf("SIP/Proxy_ESN-00000002", "0?exit,return") in new stack
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Not taking any branch
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'Set'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-exten-vm:11] Set("SIP/Proxy_ESN-00000002", "SV_DIALSTATUS=CHANUNAVAIL") in new stack
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: Set
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '0'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '0'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '1'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '0'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'GosubIf'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-exten-vm:12] GosubIf("SIP/Proxy_ESN-00000002", "0?docfu,1") in new stack
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: GosubIf
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '0'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '0'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '1'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '0'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '0'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '0'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '0'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'GosubIf'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-exten-vm:13] GosubIf("SIP/Proxy_ESN-00000002", "0?docfb,1") in new stack
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: GosubIf
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '0'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '0'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '0'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'Set'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-exten-vm:14] Set("SIP/Proxy_ESN-00000002", "DIALSTATUS=CHANUNAVAIL") in new stack
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: Set
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'NoOp'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-exten-vm:15] NoOp("SIP/Proxy_ESN-00000002", "Voicemail is '9999'") in new stack
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: NoOp
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '0'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-exten-vm:16] GotoIf("SIP/Proxy_ESN-00000002", "0?s-CHANUNAVAIL,1") in new stack
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Not taking any branch
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'NoOp'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-exten-vm:17] NoOp("SIP/Proxy_ESN-00000002", "Sending to Voicemail box 9999") in new stack
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: NoOp
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'Macro'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-exten-vm:18] Macro("SIP/Proxy_ESN-00000002", "vm,9999,CHANUNAVAIL,") in new stack
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'Macro'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-vm:1] Macro("SIP/Proxy_ESN-00000002", "user-callerid,SKIPTTL") in new stack
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '1'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Function result is '008029'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Function result is '008029'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'Set'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-user-callerid:1] Set("SIP/Proxy_ESN-00000002", "AMPUSER=008029") in new stack
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: Set
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '0'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-user-callerid:2] GotoIf("SIP/Proxy_ESN-00000002", "0?report") in new stack
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Not taking any branch
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '0'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Function result is '008029'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'ExecIf'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-user-callerid:3] ExecIf("SIP/Proxy_ESN-00000002", "0?Set(REALCALLERIDNUM=008029)") in new stack
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: ExecIf
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '0'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Function result is '008029'
[Jul 30 13:57:32] DEBUG[21540] db.c: Unable to find key '008029/user' in family 'DEVICE'
[Jul 30 13:57:32] DEBUG[21540] func_db.c: DB: DEVICE/008029/user not found in database.
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Function result is ''
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'Set'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-user-callerid:4] Set("SIP/Proxy_ESN-00000002", "AMPUSER=") in new stack
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: Set
[Jul 30 13:57:32] DEBUG[21540] db.c: Unable to find key '/cidname' in family 'AMPUSER'
[Jul 30 13:57:32] DEBUG[21540] func_db.c: DB: AMPUSER//cidname not found in database.
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Function result is ''
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'Set'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-user-callerid:5] Set("SIP/Proxy_ESN-00000002", "AMPUSERCIDNAME=") in new stack
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: Set
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '1'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-user-callerid:6] GotoIf("SIP/Proxy_ESN-00000002", "1?report") in new stack
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Goto (macro-user-callerid,s,10)
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '1'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-user-callerid:10] GotoIf("SIP/Proxy_ESN-00000002", "1?continue") in new stack
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Goto (macro-user-callerid,s,19)
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Function result is '"GUTZKE KLAUS" <008029>'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'NoOp'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-user-callerid:19] NoOp("SIP/Proxy_ESN-00000002", "Using CallerID "GUTZKE KLAUS" <008029>") in new stack
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: Noop
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: Macro
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '0'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Function result is '""'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'Set'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-vm:2] Set("SIP/Proxy_ESN-00000002", "VMGAIN=""") in new stack
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: Set
[Jul 30 13:57:32] WARNING[21540] func_db.c: DB requires an argument, DB(<family>/<key>)
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Function result is '(null)'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '1'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-vm:3] GotoIf("SIP/Proxy_ESN-00000002", "1?vmx,1") in new stack
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Goto (macro-vm,vmx,1)
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '0'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [vmx@macro-vm:1] GotoIf("SIP/Proxy_ESN-00000002", "0?s-CHANUNAVAIL,1") in new stack
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Not taking any branch
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '0'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Function result is 'unavail'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'Set'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [vmx@macro-vm:2] Set("SIP/Proxy_ESN-00000002", "MODE=unavail") in new stack
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: Set
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '1'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [vmx@macro-vm:3] GotoIf("SIP/Proxy_ESN-00000002", "1?notdirect") in new stack
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Goto (macro-vm,vmx,5)
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:32] DEBUG[21540] db.c: Unable to find key '9999/vmx/unavail/state' in family 'AMPUSER'
[Jul 30 13:57:32] DEBUG[21540] func_db.c: DB: AMPUSER/9999/vmx/unavail/state not found in database.
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Function result is ''
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'NoOp'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [vmx@macro-vm:5] NoOp("SIP/Proxy_ESN-00000002", "Checking if ext 9999 is enabled: ") in new stack
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: Noop
[Jul 30 13:57:32] DEBUG[21540] db.c: Unable to find key '9999/vmx/unavail/state' in family 'AMPUSER'
[Jul 30 13:57:32] DEBUG[21540] func_db.c: DB: AMPUSER/9999/vmx/unavail/state not found in database.
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Function result is ''
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '1'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [vmx@macro-vm:6] GotoIf("SIP/Proxy_ESN-00000002", "1?s-CHANUNAVAIL,1") in new stack
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Goto (macro-vm,s-CHANUNAVAIL,1)
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'Macro'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s-CHANUNAVAIL@macro-vm:1] Macro("SIP/Proxy_ESN-00000002", "get-vmcontext,9999") in new stack
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Function result is 'default'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'Set'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-get-vmcontext:1] Set("SIP/Proxy_ESN-00000002", "VMCONTEXT=default") in new stack
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: Set
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Expression result is '0'
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-get-vmcontext:2] GotoIf("SIP/Proxy_ESN-00000002", "0?200:300") in new stack
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Goto (macro-get-vmcontext,s,300)
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'NoOp'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s@macro-get-vmcontext:300] NoOp("SIP/Proxy_ESN-00000002", "") in new stack
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: NoOp
[Jul 30 13:57:32] DEBUG[21540] app_macro.c: Executed application: Macro
[Jul 30 13:57:32] DEBUG[21540] pbx.c: Launching 'VoiceMail'
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- Executing [s-CHANUNAVAIL@macro-vm:2] VoiceMail("SIP/Proxy_ESN-00000002", "9999@default,u""") in new stack
[Jul 30 13:57:32] DEBUG[21540] chan_sip.c: SIP answering channel: SIP/Proxy_ESN-00000002
[Jul 30 13:57:32] DEBUG[21540] chan_sip.c: Setting framing from config on incoming call
[Jul 30 13:57:32] DEBUG[21540] chan_sip.c: ** Our capability: 0x28000c (ulaw|alaw|h263|h264) Video flag: False Text flag: True
[Jul 30 13:57:32] DEBUG[21540] chan_sip.c: ** Our prefcodec: 0x0 (nothing) 
[Jul 30 13:57:32] DEBUG[21540] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 156.150.133.165:5060
[Jul 30 13:57:32] DEBUG[21500] chan_sip.c: Stopping retransmission on '2e3bbb290fdd1abf3a09c4083961e09c@156.150.133.165' of Response 102: Match Found
[Jul 30 13:57:32] DEBUG[21540] chan_sip.c: Oooh, format changed to 8 alaw
[Jul 30 13:57:32] DEBUG[21540] channel.c: Set channel SIP/Proxy_ESN-00000002 to read format ulaw
[Jul 30 13:57:32] DEBUG[21540] channel.c: Set channel SIP/Proxy_ESN-00000002 to write format ulaw
[Jul 30 13:57:32] DEBUG[21540] app_voicemail.c: /var/spool/asterisk/voicemail/default/9999/unavail doesn't exist, doing what we can
[Jul 30 13:57:32] DEBUG[21540] channel.c: Set channel SIP/Proxy_ESN-00000002 to write format slin
[Jul 30 13:57:32] DEBUG[21540] rtp.c: Ooh, format changed from unknown to alaw
[Jul 30 13:57:32] DEBUG[21540] rtp.c: Created smoother: format: 8 ms: 20 len: 160
[Jul 30 13:57:32] VERBOSE[21540] logger.c:     -- <SIP/Proxy_ESN-00000002> Playing 'vm-theperson.slin' (language 'de')
[Jul 30 13:57:32] NOTICE[21540] channel.c: Dropping incompatible voice frame on SIP/Proxy_ESN-00000002 of format ulaw since our native format has changed to 0x280008 (alaw|h263|h264)
[Jul 30 13:57:34] DEBUG[21540] channel.c: Set channel SIP/Proxy_ESN-00000002 to write format ulaw
[Jul 30 13:57:34] DEBUG[21540] channel.c: Set channel SIP/Proxy_ESN-00000002 to write format slin
[Jul 30 13:57:34] VERBOSE[21540] logger.c:     -- <SIP/Proxy_ESN-00000002> Playing 'digits/9.slin' (language 'de')
[Jul 30 13:57:35] DEBUG[21540] channel.c: Set channel SIP/Proxy_ESN-00000002 to write format ulaw
[Jul 30 13:57:35] DEBUG[21540] channel.c: Set channel SIP/Proxy_ESN-00000002 to write format slin
[Jul 30 13:57:35] VERBOSE[21540] logger.c:     -- <SIP/Proxy_ESN-00000002> Playing 'digits/9.slin' (language 'de')
[Jul 30 13:57:35] DEBUG[21540] channel.c: Set channel SIP/Proxy_ESN-00000002 to write format ulaw
[Jul 30 13:57:35] DEBUG[21540] channel.c: Set channel SIP/Proxy_ESN-00000002 to write format slin
[Jul 30 13:57:35] VERBOSE[21540] logger.c:     -- <SIP/Proxy_ESN-00000002> Playing 'digits/9.slin' (language 'de')
[Jul 30 13:57:36] DEBUG[21540] channel.c: Set channel SIP/Proxy_ESN-00000002 to write format ulaw
[Jul 30 13:57:36] DEBUG[21540] channel.c: Set channel SIP/Proxy_ESN-00000002 to write format slin
[Jul 30 13:57:36] VERBOSE[21540] logger.c:     -- <SIP/Proxy_ESN-00000002> Playing 'digits/9.slin' (language 'de')
[Jul 30 13:57:37] DEBUG[21540] channel.c: Set channel SIP/Proxy_ESN-00000002 to write format ulaw
[Jul 30 13:57:37] DEBUG[21540] channel.c: Set channel SIP/Proxy_ESN-00000002 to write format slin
[Jul 30 13:57:37] VERBOSE[21540] logger.c:     -- <SIP/Proxy_ESN-00000002> Playing 'vm-isunavail.slin' (language 'de')
[Jul 30 13:57:38] DEBUG[21540] channel.c: Set channel SIP/Proxy_ESN-00000002 to write format ulaw
[Jul 30 13:57:38] DEBUG[21540] channel.c: Set channel SIP/Proxy_ESN-00000002 to write format slin
[Jul 30 13:57:38] VERBOSE[21540] logger.c:     -- <SIP/Proxy_ESN-00000002> Playing 'vm-intro.slin' (language 'de')
[Jul 30 13:57:40] DEBUG[21500] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jul 30 13:57:40] DEBUG[21500] chan_sip.c: Initializing initreq for method OPTIONS - callid 7cdf3ea22a69e91435d0289812b247ac@156.150.132.46
[Jul 30 13:57:40] DEBUG[21500] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 156.150.133.165:5060
[Jul 30 13:57:40] DEBUG[21500] chan_sip.c: Stopping retransmission on '7cdf3ea22a69e91435d0289812b247ac@156.150.132.46' of Request 102: Match Found
[Jul 30 13:57:44] DEBUG[21540] channel.c: Set channel SIP/Proxy_ESN-00000002 to write format ulaw
[Jul 30 13:57:44] DEBUG[21540] app_voicemail.c: IMAP Info: Reusing connection to 156.150.130.20/user="A100670@deuser.de.intra\A100658"
[Jul 30 13:57:44] DEBUG[21540] app_voicemail.c: IMAP Info: [UNSEEN 1] Is the first unseen message
[Jul 30 13:57:44] DEBUG[21540] app_voicemail.c: IMAP Info: Reusing connection to 156.150.130.20/user="A100670@deuser.de.intra\A100658"
[Jul 30 13:57:44] DEBUG[21540] app_voicemail.c: IMAP Info: [UNSEEN 1] Is the first unseen message
[Jul 30 13:57:44] ERROR[21540] app_voicemail.c: IMAP Error: Quota not available on this IMAP server
[Jul 30 13:57:44] DEBUG[21540] channel.c: Set channel SIP/Proxy_ESN-00000002 to write format slin
[Jul 30 13:57:44] VERBOSE[21540] logger.c:     -- <SIP/Proxy_ESN-00000002> Playing 'beep.slin' (language 'de')
[Jul 30 13:57:44] DEBUG[21540] channel.c: Set channel SIP/Proxy_ESN-00000002 to write format ulaw
[Jul 30 13:57:44] VERBOSE[21540] logger.c:     -- Recording the message
[Jul 30 13:57:44] DEBUG[21540] app.c: play_and_record: <None>, /var/spool/asterisk/voicemail/default/9999/tmp/mz7sci, 'wav49|gsm|wav'
[Jul 30 13:57:44] DEBUG[21540] app.c: Recording Formats: sfmts=wav49
[Jul 30 13:57:44] VERBOSE[21540] logger.c:     -- x=0, open writing:  /var/spool/asterisk/voicemail/default/9999/tmp/mz7sci format: wav49, 0x84e1748
[Jul 30 13:57:44] VERBOSE[21540] logger.c:     -- x=1, open writing:  /var/spool/asterisk/voicemail/default/9999/tmp/mz7sci format: gsm, 0x85314e0
[Jul 30 13:57:44] VERBOSE[21540] logger.c:     -- x=2, open writing:  /var/spool/asterisk/voicemail/default/9999/tmp/mz7sci format: wav, 0x84cf590
[Jul 30 13:57:44] DEBUG[21540] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[Jul 30 13:57:44] DEBUG[21540] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[Jul 30 13:57:44] DEBUG[21540] channel.c: Set channel SIP/Proxy_ESN-00000002 to read format slin
[Jul 30 13:57:44] DEBUG[21540] chan_sip.c: Trying to put 'INFO sip:00' onto UDP socket destined for 156.150.133.165:5060
[Jul 30 13:57:44] DEBUG[21500] chan_sip.c: Stopping retransmission on '2e3bbb290fdd1abf3a09c4083961e09c@156.150.133.165' of Request 102: Match Found
[Jul 30 13:57:49] DEBUG[21500] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 156.150.133.165:5060
[Jul 30 13:57:49] VERBOSE[21540] logger.c:     -- User hung up
[Jul 30 13:57:49] DEBUG[21540] channel.c: Set channel SIP/Proxy_ESN-00000002 to read format ulaw
[Jul 30 13:57:49] DEBUG[21540] app.c: Locked path '/var/spool/asterisk/voicemail/default/9999/INBOX'
[Jul 30 13:57:49] DEBUG[21540] app.c: Unlocked path '/var/spool/asterisk/voicemail/default/9999/INBOX'
[Jul 30 13:57:49] DEBUG[21540] app_voicemail.c: IMAP Info: Reusing connection to 156.150.130.20/user="A100670@deuser.de.intra\A100658"
[Jul 30 13:57:49] DEBUG[21540] app_voicemail.c: IMAP Info: [UNSEEN 1] Is the first unseen message
[Jul 30 13:57:49] DEBUG[21540] app_voicemail.c: IMAP Info: Reusing connection to 156.150.130.20/user="A100670@deuser.de.intra\A100658"
[Jul 30 13:57:49] DEBUG[21540] app_voicemail.c: IMAP Info: [UNSEEN 1] Is the first unseen message
[Jul 30 13:57:49] ERROR[21540] app_voicemail.c: IMAP Error: Quota not available on this IMAP server
[Jul 30 13:57:49] DEBUG[21540] app_voicemail.c: IMAP Info: Reusing connection to 156.150.130.20/user="A100670@deuser.de.intra\A100658"
[Jul 30 13:57:49] DEBUG[21540] app_voicemail.c: IMAP Info: [UNSEEN 1] Is the first unseen message
[Jul 30 13:57:49] DEBUG[21540] app_voicemail.c: IMAP Info: [APPENDUID 430865 4] APPEND completed.
[Jul 30 13:57:49] DEBUG[21540] app_voicemail.c: IMAP Info: Reusing connection to 156.150.130.20/user="A100670@deuser.de.intra\A100658"
[Jul 30 13:57:49] DEBUG[21540] app_voicemail.c: IMAP Info: [UNSEEN 1] Is the first unseen message
[Jul 30 13:57:49] DEBUG[21540] app_voicemail.c: IMAP Info: Reusing connection to 156.150.130.20/user="A100670@deuser.de.intra\A100658"
[Jul 30 13:57:49] DEBUG[21540] app_voicemail.c: IMAP Info: [UNSEEN 1] Is the first unseen message
[Jul 30 13:57:50] DEBUG[21540] app_voicemail.c: IMAP Info: Reusing connection to 156.150.130.20/user="A100670@deuser.de.intra\A100658"
[Jul 30 13:57:50] DEBUG[21540] app_voicemail.c: IMAP Info: [UNSEEN 1] Is the first unseen message
[Jul 30 13:57:50] DEBUG[21540] app_voicemail.c: IMAP Info: Reusing connection to 156.150.130.20/user="A100670@deuser.de.intra\A100658"
[Jul 30 13:57:50] DEBUG[21540] app_voicemail.c: IMAP Info: [UNSEEN 1] Is the first unseen message
[Jul 30 13:57:50] VERBOSE[21540] logger.c:   == Spawn extension (macro-vm, s-CHANUNAVAIL, 2) exited non-zero on 'SIP/Proxy_ESN-00000002' in macro 'vm'
[Jul 30 13:57:50] VERBOSE[21540] logger.c:   == Spawn extension (macro-exten-vm, s, 18) exited non-zero on 'SIP/Proxy_ESN-00000002' in macro 'exten-vm'
[Jul 30 13:57:50] DEBUG[21540] pbx.c: Spawn extension (from-internal,9999,1) exited non-zero on 'SIP/Proxy_ESN-00000002'
[Jul 30 13:57:50] VERBOSE[21540] logger.c:   == Spawn extension (from-internal, 9999, 1) exited non-zero on 'SIP/Proxy_ESN-00000002'
[Jul 30 13:57:50] DEBUG[21540] channel.c: Soft-Hanging up channel 'SIP/Proxy_ESN-00000002'
[Jul 30 13:57:50] DEBUG[21540] pbx.c: Launching 'Macro'
[Jul 30 13:57:50] VERBOSE[21540] logger.c:     -- Executing [h@from-internal:1] Macro("SIP/Proxy_ESN-00000002", "hangupcall") in new stack
[Jul 30 13:57:50] DEBUG[21540] pbx.c: Expression result is '1'
[Jul 30 13:57:50] DEBUG[21540] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:50] VERBOSE[21540] logger.c:     -- Executing [s@macro-hangupcall:1] GotoIf("SIP/Proxy_ESN-00000002", "1?skiprg") in new stack
[Jul 30 13:57:50] VERBOSE[21540] logger.c:     -- Goto (macro-hangupcall,s,4)
[Jul 30 13:57:50] DEBUG[21540] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:50] DEBUG[21540] pbx.c: Expression result is '1'
[Jul 30 13:57:50] DEBUG[21540] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:50] VERBOSE[21540] logger.c:     -- Executing [s@macro-hangupcall:4] GotoIf("SIP/Proxy_ESN-00000002", "1?skipblkvm") in new stack
[Jul 30 13:57:50] VERBOSE[21540] logger.c:     -- Goto (macro-hangupcall,s,7)
[Jul 30 13:57:50] DEBUG[21540] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:50] DEBUG[21540] pbx.c: Expression result is '1'
[Jul 30 13:57:50] DEBUG[21540] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:50] VERBOSE[21540] logger.c:     -- Executing [s@macro-hangupcall:7] GotoIf("SIP/Proxy_ESN-00000002", "1?theend") in new stack
[Jul 30 13:57:50] VERBOSE[21540] logger.c:     -- Goto (macro-hangupcall,s,9)
[Jul 30 13:57:50] DEBUG[21540] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:50] DEBUG[21540] pbx.c: Launching 'Hangup'
[Jul 30 13:57:50] VERBOSE[21540] logger.c:     -- Executing [s@macro-hangupcall:9] Hangup("SIP/Proxy_ESN-00000002", "") in new stack
[Jul 30 13:57:50] VERBOSE[21540] logger.c:   == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'SIP/Proxy_ESN-00000002' in macro 'hangupcall'
[Jul 30 13:57:50] DEBUG[21540] pbx.c: Spawn extension (from-internal,h,1) exited non-zero on 'SIP/Proxy_ESN-00000002'
[Jul 30 13:57:50] VERBOSE[21540] logger.c:   == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/Proxy_ESN-00000002'
[Jul 30 13:57:50] DEBUG[21540] channel.c: Hanging up channel 'SIP/Proxy_ESN-00000002'
[Jul 30 13:57:50] DEBUG[21540] chan_sip.c: Hangup call SIP/Proxy_ESN-00000002, SIP callid 2e3bbb290fdd1abf3a09c4083961e09c@156.150.133.165
[Jul 30 13:57:58] VERBOSE[21500] logger.c:   == Using SIP RTP TOS bits 184
[Jul 30 13:57:58] VERBOSE[21500] logger.c:   == Using SIP RTP CoS mark 5
[Jul 30 13:57:58] VERBOSE[21500] logger.c:   == Using SIP VRTP TOS bits 136
[Jul 30 13:57:58] VERBOSE[21500] logger.c:   == Using SIP VRTP CoS mark 6
[Jul 30 13:57:58] DEBUG[21500] chan_sip.c: Setting NAT on RTP to Off
[Jul 30 13:57:58] DEBUG[21500] chan_sip.c: Setting NAT on VRTP to Off
[Jul 30 13:57:58] DEBUG[21500] chan_sip.c: Allocating new SIP dialog for 1f4a294a0743d5a659ef22e96f17d56a@156.150.133.165 - INVITE (With RTP)
[Jul 30 13:57:58] DEBUG[21500] chan_sip.c: Setting NAT on RTP to Off
[Jul 30 13:57:58] DEBUG[21500] chan_sip.c: Setting NAT on VRTP to Off
[Jul 30 13:57:58] DEBUG[21500] chan_sip.c: Checking SIP call limits for device esn
[Jul 30 13:57:58] DEBUG[21500] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 156.150.133.165:5060
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'Macro'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [9999@from-internal:1] Macro("SIP/Proxy_ESN-00000003", "exten-vm,9999,9999") in new stack
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'Macro'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-exten-vm:1] Macro("SIP/Proxy_ESN-00000003", "user-callerid") in new stack
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '1'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Function result is '008029'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Function result is '008029'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'Set'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-user-callerid:1] Set("SIP/Proxy_ESN-00000003", "AMPUSER=008029") in new stack
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: Set
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '0'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-user-callerid:2] GotoIf("SIP/Proxy_ESN-00000003", "0?report") in new stack
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Not taking any branch
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '1'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Function result is '008029'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'ExecIf'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-user-callerid:3] ExecIf("SIP/Proxy_ESN-00000003", "1?Set(REALCALLERIDNUM=008029)") in new stack
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: ExecIf
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '0'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Function result is '008029'
[Jul 30 13:57:58] DEBUG[21544] db.c: Unable to find key '008029/user' in family 'DEVICE'
[Jul 30 13:57:58] DEBUG[21544] func_db.c: DB: DEVICE/008029/user not found in database.
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Function result is ''
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'Set'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-user-callerid:4] Set("SIP/Proxy_ESN-00000003", "AMPUSER=") in new stack
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: Set
[Jul 30 13:57:58] DEBUG[21544] db.c: Unable to find key '/cidname' in family 'AMPUSER'
[Jul 30 13:57:58] DEBUG[21544] func_db.c: DB: AMPUSER//cidname not found in database.
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Function result is ''
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'Set'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-user-callerid:5] Set("SIP/Proxy_ESN-00000003", "AMPUSERCIDNAME=") in new stack
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: Set
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '1'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-user-callerid:6] GotoIf("SIP/Proxy_ESN-00000003", "1?report") in new stack
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Goto (macro-user-callerid,s,10)
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '0'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-user-callerid:10] GotoIf("SIP/Proxy_ESN-00000003", "0?continue") in new stack
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Not taking any branch
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '1'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '-1'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Function result is '64'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'Set'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-user-callerid:11] Set("SIP/Proxy_ESN-00000003", "__TTL=64") in new stack
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: Set
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '1'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-user-callerid:12] GotoIf("SIP/Proxy_ESN-00000003", "1?continue") in new stack
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Goto (macro-user-callerid,s,19)
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Function result is '"GUTZKE KLAUS" <008029>'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'NoOp'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-user-callerid:19] NoOp("SIP/Proxy_ESN-00000003", "Using CallerID "GUTZKE KLAUS" <008029>") in new stack
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: Noop
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: Macro
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'Set'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-exten-vm:2] Set("SIP/Proxy_ESN-00000003", "RingGroupMethod=none") in new stack
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: Set
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'Set'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-exten-vm:3] Set("SIP/Proxy_ESN-00000003", "VMBOX=9999") in new stack
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: Set
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'Set'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-exten-vm:4] Set("SIP/Proxy_ESN-00000003", "EXTTOCALL=9999") in new stack
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: Set
[Jul 30 13:57:58] DEBUG[21544] db.c: Unable to find key '9999' in family 'CFU'
[Jul 30 13:57:58] DEBUG[21544] func_db.c: DB: CFU/9999 not found in database.
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Function result is ''
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'Set'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-exten-vm:5] Set("SIP/Proxy_ESN-00000003", "CFUEXT=") in new stack
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: Set
[Jul 30 13:57:58] DEBUG[21544] db.c: Unable to find key '9999' in family 'CFB'
[Jul 30 13:57:58] DEBUG[21544] func_db.c: DB: CFB/9999 not found in database.
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Function result is ''
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'Set'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-exten-vm:6] Set("SIP/Proxy_ESN-00000003", "CFBEXT=") in new stack
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: Set
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '1'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '0'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '1'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Function result is '15'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'Set'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-exten-vm:7] Set("SIP/Proxy_ESN-00000003", "RT=15") in new stack
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: Set
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'Macro'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-exten-vm:8] Macro("SIP/Proxy_ESN-00000003", "record-enable,9999,IN") in new stack
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '1'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-record-enable:1] GotoIf("SIP/Proxy_ESN-00000003", "1?check") in new stack
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Goto (macro-record-enable,s,4)
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Function result is '20100730-135758'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'AGI'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-record-enable:4] AGI("SIP/Proxy_ESN-00000003", "recordingcheck,20100730-135758,1280491078.3") in new stack
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
[Jul 30 13:57:58] VERBOSE[21544] logger.c:  recordingcheck,20100730-135758,1280491078.3: Inbound recording not enabled
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- <SIP/Proxy_ESN-00000003>AGI Script recordingcheck completed, returning 0
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: AGI
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'MacroExit'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-record-enable:5] MacroExit("SIP/Proxy_ESN-00000003", "") in new stack
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: Macro
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'Macro'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-exten-vm:9] Macro("SIP/Proxy_ESN-00000003", "dial,15,tr,9999") in new stack
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '1'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-dial:1] GotoIf("SIP/Proxy_ESN-00000003", "1?dial") in new stack
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Goto (macro-dial,s,3)
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'AGI'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-dial:3] AGI("SIP/Proxy_ESN-00000003", "dialparties.agi") in new stack
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
[Jul 30 13:57:58] VERBOSE[21544] logger.c:  dialparties.agi: Starting New Dialparties.agi
[Jul 30 13:57:58] VERBOSE[21544] logger.c:  dialparties.agi: Caller ID name is 'GUTZKE KLAUS' number is '008029'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:        > dialparties.agi: USE_CONFIRMATION:  'FALSE'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:        > dialparties.agi: RINGGROUP_INDEX:   ''
[Jul 30 13:57:58] VERBOSE[21544] logger.c:  dialparties.agi: Methodology of ring is  'none'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- dialparties.agi: Added extension 9999 to extension map
[Jul 30 13:57:58] DEBUG[21544] db.c: Unable to find key '9999' in family 'CF'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- dialparties.agi: Extension 9999 cf is disabled
[Jul 30 13:57:58] DEBUG[21544] db.c: Unable to find key '9999' in family 'DND'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- dialparties.agi: Extension 9999 do not disturb is disabled
[Jul 30 13:57:58] DEBUG[21544] db.c: Unable to find key '9999' in family 'CFB'
[Jul 30 13:57:58] DEBUG[21544] db.c: Unable to find key '9999' in family 'CFU'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:        > dialparties.agi: extnum 9999 has:  cw: 1; hascfb: 0 [] hascfu: 0 []
[Jul 30 13:57:58] DEBUG[21544] db.c: Unable to find key 'DND9999' in family 'CustomDevstate'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:  dialparties.agi: EXTENSION_STATE: 4 (UNAVAILABLE)
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- dialparties.agi: dbset CALLTRACE/9999 to 008029
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- dialparties.agi: Filtered ARG3: 9999
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- <SIP/Proxy_ESN-00000003>AGI Script dialparties.agi completed, returning 0
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: AGI
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'Dial'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-dial:7] Dial("SIP/Proxy_ESN-00000003", "SIP/9999,15,tr") in new stack
[Jul 30 13:57:58] DEBUG[21544] chan_sip.c: Asked to create a SIP channel with formats: 0x280004 (ulaw|h263|h264)
[Jul 30 13:57:58] VERBOSE[21544] logger.c:   == Using SIP RTP TOS bits 184
[Jul 30 13:57:58] VERBOSE[21544] logger.c:   == Using SIP RTP CoS mark 5
[Jul 30 13:57:58] VERBOSE[21544] logger.c:   == Using SIP VRTP TOS bits 136
[Jul 30 13:57:58] VERBOSE[21544] logger.c:   == Using SIP VRTP CoS mark 6
[Jul 30 13:57:58] DEBUG[21544] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
[Jul 30 13:57:58] WARNING[21544] app_dial.c: Unable to create channel of type 'SIP' (cause 20 - Unknown)
[Jul 30 13:57:58] VERBOSE[21544] logger.c:   == Everyone is busy/congested at this time (1:0/0/1)
[Jul 30 13:57:58] DEBUG[21544] rtp.c: Channel '<unspecified>' has no RTP, not doing anything
[Jul 30 13:57:58] DEBUG[21544] app_dial.c: Exiting with DIALSTATUS=CHANUNAVAIL.
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: Dial
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '0'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Function result is 'CHANUNAVAIL'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'Set'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-dial:8] Set("SIP/Proxy_ESN-00000003", "DIALSTATUS=CHANUNAVAIL") in new stack
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: Set
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '0'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'GosubIf'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-dial:9] GosubIf("SIP/Proxy_ESN-00000003", "0?CHANUNAVAIL,1") in new stack
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: GosubIf
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '0'
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: Macro
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '1'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '0'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '0'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '0'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-exten-vm:10] GotoIf("SIP/Proxy_ESN-00000003", "0?exit,return") in new stack
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Not taking any branch
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'Set'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-exten-vm:11] Set("SIP/Proxy_ESN-00000003", "SV_DIALSTATUS=CHANUNAVAIL") in new stack
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: Set
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '0'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '0'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '1'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '0'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'GosubIf'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-exten-vm:12] GosubIf("SIP/Proxy_ESN-00000003", "0?docfu,1") in new stack
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: GosubIf
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '0'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '0'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '1'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '0'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '0'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '0'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '0'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'GosubIf'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-exten-vm:13] GosubIf("SIP/Proxy_ESN-00000003", "0?docfb,1") in new stack
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: GosubIf
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '0'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '0'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '0'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'Set'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-exten-vm:14] Set("SIP/Proxy_ESN-00000003", "DIALSTATUS=CHANUNAVAIL") in new stack
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: Set
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'NoOp'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-exten-vm:15] NoOp("SIP/Proxy_ESN-00000003", "Voicemail is '9999'") in new stack
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: NoOp
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '0'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-exten-vm:16] GotoIf("SIP/Proxy_ESN-00000003", "0?s-CHANUNAVAIL,1") in new stack
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Not taking any branch
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'NoOp'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-exten-vm:17] NoOp("SIP/Proxy_ESN-00000003", "Sending to Voicemail box 9999") in new stack
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: NoOp
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'Macro'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-exten-vm:18] Macro("SIP/Proxy_ESN-00000003", "vm,9999,CHANUNAVAIL,") in new stack
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'Macro'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-vm:1] Macro("SIP/Proxy_ESN-00000003", "user-callerid,SKIPTTL") in new stack
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '1'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Function result is '008029'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Function result is '008029'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'Set'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-user-callerid:1] Set("SIP/Proxy_ESN-00000003", "AMPUSER=008029") in new stack
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: Set
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '0'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-user-callerid:2] GotoIf("SIP/Proxy_ESN-00000003", "0?report") in new stack
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Not taking any branch
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '0'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Function result is '008029'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'ExecIf'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-user-callerid:3] ExecIf("SIP/Proxy_ESN-00000003", "0?Set(REALCALLERIDNUM=008029)") in new stack
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: ExecIf
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '0'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Function result is '008029'
[Jul 30 13:57:58] DEBUG[21544] db.c: Unable to find key '008029/user' in family 'DEVICE'
[Jul 30 13:57:58] DEBUG[21544] func_db.c: DB: DEVICE/008029/user not found in database.
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Function result is ''
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'Set'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-user-callerid:4] Set("SIP/Proxy_ESN-00000003", "AMPUSER=") in new stack
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: Set
[Jul 30 13:57:58] DEBUG[21544] db.c: Unable to find key '/cidname' in family 'AMPUSER'
[Jul 30 13:57:58] DEBUG[21544] func_db.c: DB: AMPUSER//cidname not found in database.
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Function result is ''
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'Set'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-user-callerid:5] Set("SIP/Proxy_ESN-00000003", "AMPUSERCIDNAME=") in new stack
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: Set
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '1'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-user-callerid:6] GotoIf("SIP/Proxy_ESN-00000003", "1?report") in new stack
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Goto (macro-user-callerid,s,10)
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '1'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-user-callerid:10] GotoIf("SIP/Proxy_ESN-00000003", "1?continue") in new stack
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Goto (macro-user-callerid,s,19)
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Function result is '"GUTZKE KLAUS" <008029>'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'NoOp'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-user-callerid:19] NoOp("SIP/Proxy_ESN-00000003", "Using CallerID "GUTZKE KLAUS" <008029>") in new stack
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: Noop
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: Macro
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '0'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Function result is '""'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'Set'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-vm:2] Set("SIP/Proxy_ESN-00000003", "VMGAIN=""") in new stack
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: Set
[Jul 30 13:57:58] WARNING[21544] func_db.c: DB requires an argument, DB(<family>/<key>)
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Function result is '(null)'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '1'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-vm:3] GotoIf("SIP/Proxy_ESN-00000003", "1?vmx,1") in new stack
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Goto (macro-vm,vmx,1)
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '0'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [vmx@macro-vm:1] GotoIf("SIP/Proxy_ESN-00000003", "0?s-CHANUNAVAIL,1") in new stack
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Not taking any branch
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '0'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Function result is 'unavail'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'Set'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [vmx@macro-vm:2] Set("SIP/Proxy_ESN-00000003", "MODE=unavail") in new stack
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: Set
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '1'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [vmx@macro-vm:3] GotoIf("SIP/Proxy_ESN-00000003", "1?notdirect") in new stack
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Goto (macro-vm,vmx,5)
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:58] DEBUG[21544] db.c: Unable to find key '9999/vmx/unavail/state' in family 'AMPUSER'
[Jul 30 13:57:58] DEBUG[21544] func_db.c: DB: AMPUSER/9999/vmx/unavail/state not found in database.
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Function result is ''
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'NoOp'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [vmx@macro-vm:5] NoOp("SIP/Proxy_ESN-00000003", "Checking if ext 9999 is enabled: ") in new stack
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: Noop
[Jul 30 13:57:58] DEBUG[21544] db.c: Unable to find key '9999/vmx/unavail/state' in family 'AMPUSER'
[Jul 30 13:57:58] DEBUG[21544] func_db.c: DB: AMPUSER/9999/vmx/unavail/state not found in database.
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Function result is ''
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '1'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [vmx@macro-vm:6] GotoIf("SIP/Proxy_ESN-00000003", "1?s-CHANUNAVAIL,1") in new stack
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Goto (macro-vm,s-CHANUNAVAIL,1)
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'Macro'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s-CHANUNAVAIL@macro-vm:1] Macro("SIP/Proxy_ESN-00000003", "get-vmcontext,9999") in new stack
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Function result is 'default'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'Set'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-get-vmcontext:1] Set("SIP/Proxy_ESN-00000003", "VMCONTEXT=default") in new stack
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: Set
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Expression result is '0'
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-get-vmcontext:2] GotoIf("SIP/Proxy_ESN-00000003", "0?200:300") in new stack
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Goto (macro-get-vmcontext,s,300)
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'NoOp'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s@macro-get-vmcontext:300] NoOp("SIP/Proxy_ESN-00000003", "") in new stack
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: NoOp
[Jul 30 13:57:58] DEBUG[21544] app_macro.c: Executed application: Macro
[Jul 30 13:57:58] DEBUG[21544] pbx.c: Launching 'VoiceMail'
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- Executing [s-CHANUNAVAIL@macro-vm:2] VoiceMail("SIP/Proxy_ESN-00000003", "9999@default,u""") in new stack
[Jul 30 13:57:58] DEBUG[21544] chan_sip.c: SIP answering channel: SIP/Proxy_ESN-00000003
[Jul 30 13:57:58] DEBUG[21544] chan_sip.c: Setting framing from config on incoming call
[Jul 30 13:57:58] DEBUG[21544] chan_sip.c: ** Our capability: 0x28000c (ulaw|alaw|h263|h264) Video flag: False Text flag: True
[Jul 30 13:57:58] DEBUG[21544] chan_sip.c: ** Our prefcodec: 0x0 (nothing) 
[Jul 30 13:57:58] DEBUG[21544] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 156.150.133.165:5060
[Jul 30 13:57:58] DEBUG[21500] chan_sip.c: Stopping retransmission on '1f4a294a0743d5a659ef22e96f17d56a@156.150.133.165' of Response 102: Match Found
[Jul 30 13:57:58] DEBUG[21544] chan_sip.c: Oooh, format changed to 8 alaw
[Jul 30 13:57:58] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to read format ulaw
[Jul 30 13:57:58] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format ulaw
[Jul 30 13:57:58] DEBUG[21544] app_voicemail.c: /var/spool/asterisk/voicemail/default/9999/unavail doesn't exist, doing what we can
[Jul 30 13:57:58] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format slin
[Jul 30 13:57:58] DEBUG[21544] rtp.c: Ooh, format changed from unknown to alaw
[Jul 30 13:57:58] DEBUG[21544] rtp.c: Created smoother: format: 8 ms: 20 len: 160
[Jul 30 13:57:58] VERBOSE[21544] logger.c:     -- <SIP/Proxy_ESN-00000003> Playing 'vm-theperson.slin' (language 'de')
[Jul 30 13:57:58] NOTICE[21544] channel.c: Dropping incompatible voice frame on SIP/Proxy_ESN-00000003 of format ulaw since our native format has changed to 0x280008 (alaw|h263|h264)
[Jul 30 13:57:59] DEBUG[21544] rtp.c: Sending dtmf: 42 (*), at 156.150.133.165
[Jul 30 13:57:59] DEBUG[21544] rtp.c: Sending dtmf: 42 (*), at 156.150.133.165
[Jul 30 13:57:59] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format ulaw
[Jul 30 13:57:59] DEBUG[21544] app_macro.c: Executed application: VoiceMail
[Jul 30 13:57:59] DEBUG[21544] pbx.c: Launching 'Macro'
[Jul 30 13:57:59] VERBOSE[21544] logger.c:     -- Executing [a@macro-vm:1] Macro("SIP/Proxy_ESN-00000003", "get-vmcontext,9999") in new stack
[Jul 30 13:57:59] DEBUG[21544] pbx.c: Function result is 'default'
[Jul 30 13:57:59] DEBUG[21544] pbx.c: Launching 'Set'
[Jul 30 13:57:59] VERBOSE[21544] logger.c:     -- Executing [s@macro-get-vmcontext:1] Set("SIP/Proxy_ESN-00000003", "VMCONTEXT=default") in new stack
[Jul 30 13:57:59] DEBUG[21544] app_macro.c: Executed application: Set
[Jul 30 13:57:59] DEBUG[21544] pbx.c: Expression result is '0'
[Jul 30 13:57:59] DEBUG[21544] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:59] VERBOSE[21544] logger.c:     -- Executing [s@macro-get-vmcontext:2] GotoIf("SIP/Proxy_ESN-00000003", "0?200:300") in new stack
[Jul 30 13:57:59] VERBOSE[21544] logger.c:     -- Goto (macro-get-vmcontext,s,300)
[Jul 30 13:57:59] DEBUG[21544] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:59] DEBUG[21544] pbx.c: Launching 'NoOp'
[Jul 30 13:57:59] VERBOSE[21544] logger.c:     -- Executing [s@macro-get-vmcontext:300] NoOp("SIP/Proxy_ESN-00000003", "") in new stack
[Jul 30 13:57:59] DEBUG[21544] app_macro.c: Executed application: NoOp
[Jul 30 13:57:59] DEBUG[21544] app_macro.c: Executed application: Macro
[Jul 30 13:57:59] DEBUG[21544] db.c: Unable to find key '9999/vmx/unavail/*/ext' in family 'AMPUSER'
[Jul 30 13:57:59] DEBUG[21544] pbx.c: Function result is '0'
[Jul 30 13:57:59] DEBUG[21544] pbx.c: Expression result is '1'
[Jul 30 13:57:59] DEBUG[21544] pbx.c: Launching 'GotoIf'
[Jul 30 13:57:59] VERBOSE[21544] logger.c:     -- Executing [a@macro-vm:2] GotoIf("SIP/Proxy_ESN-00000003", "1?adef,1") in new stack
[Jul 30 13:57:59] VERBOSE[21544] logger.c:     -- Goto (macro-vm,adef,1)
[Jul 30 13:57:59] DEBUG[21544] app_macro.c: Executed application: GotoIf
[Jul 30 13:57:59] DEBUG[21544] pbx.c: Launching 'VoiceMailMain'
[Jul 30 13:57:59] VERBOSE[21544] logger.c:     -- Executing [adef@macro-vm:1] VoiceMailMain("SIP/Proxy_ESN-00000003", "9999@default") in new stack
[Jul 30 13:57:59] DEBUG[21544] app_voicemail.c: Before find user for mailbox 9999
[Jul 30 13:57:59] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format slin
[Jul 30 13:57:59] VERBOSE[21544] logger.c:     -- <SIP/Proxy_ESN-00000003> Playing 'vm-password.slin' (language 'de')
[Jul 30 13:58:00] DEBUG[21544] rtp.c: Sending dtmf: 50 (2), at 156.150.133.165
[Jul 30 13:58:00] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format ulaw
[Jul 30 13:58:00] DEBUG[21544] rtp.c: Sending dtmf: 50 (2), at 156.150.133.165
[Jul 30 13:58:01] DEBUG[21544] rtp.c: Sending dtmf: 48 (0), at 156.150.133.165
[Jul 30 13:58:01] DEBUG[21544] rtp.c: Sending dtmf: 48 (0), at 156.150.133.165
[Jul 30 13:58:01] DEBUG[21544] rtp.c: Sending dtmf: 53 (5), at 156.150.133.165
[Jul 30 13:58:02] DEBUG[21544] rtp.c: Sending dtmf: 53 (5), at 156.150.133.165
[Jul 30 13:58:02] DEBUG[21544] rtp.c: Sending dtmf: 52 (4), at 156.150.133.165
[Jul 30 13:58:02] DEBUG[21544] rtp.c: Sending dtmf: 52 (4), at 156.150.133.165
[Jul 30 13:58:03] DEBUG[21544] rtp.c: Sending dtmf: 35 (#), at 156.150.133.165
[Jul 30 13:58:03] DEBUG[21544] rtp.c: Sending dtmf: 35 (#), at 156.150.133.165
[Jul 30 13:58:03] DEBUG[21544] app_voicemail.c: After vm_authenticate
[Jul 30 13:58:03] DEBUG[21544] app_voicemail.c: Before open_mailbox
[Jul 30 13:58:03] DEBUG[21544] app_voicemail.c: mailstream not set.
[Jul 30 13:58:03] DEBUG[21544] app_voicemail.c: IMAP Info: Trying IP address [156.150.130.20]
[Jul 30 13:58:03] DEBUG[21544] app_voicemail.c: IMAP Info: Microsoft Exchange Server 2003 IMAP4rev1 server version 6.5.7638.1 (DEESX001.deuser.de.intra) ready.
[Jul 30 13:58:03] DEBUG[21544] app_voicemail.c: IMAP Info: [UNSEEN 1] Is the first unseen message
[Jul 30 13:58:03] DEBUG[21544] app_voicemail.c: Number of old messages: 0
[Jul 30 13:58:03] DEBUG[21544] app_voicemail.c: IMAP Info: Reusing connection to 156.150.130.20/user="A100670@deuser.de.intra\A100658"
[Jul 30 13:58:03] DEBUG[21544] app_voicemail.c: IMAP Info: [UNSEEN 1] Is the first unseen message
[Jul 30 13:58:03] ERROR[21544] app_voicemail.c: IMAP Error: Quota not available on this IMAP server
[Jul 30 13:58:03] DEBUG[21544] app_voicemail.c: Number of new messages: 2
[Jul 30 13:58:03] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format slin
[Jul 30 13:58:03] VERBOSE[21544] logger.c:     -- <SIP/Proxy_ESN-00000003> Playing 'vm-youhave.slin' (language 'de')
[Jul 30 13:58:04] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format ulaw
[Jul 30 13:58:04] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format slin
[Jul 30 13:58:04] VERBOSE[21544] logger.c:     -- <SIP/Proxy_ESN-00000003> Playing 'digits/2.slin' (language 'de')
[Jul 30 13:58:05] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format ulaw
[Jul 30 13:58:05] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format slin
[Jul 30 13:58:05] VERBOSE[21544] logger.c:     -- <SIP/Proxy_ESN-00000003> Playing 'vm-INBOX.slin' (language 'de')
[Jul 30 13:58:05] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format ulaw
[Jul 30 13:58:05] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format slin
[Jul 30 13:58:05] VERBOSE[21544] logger.c:     -- <SIP/Proxy_ESN-00000003> Playing 'vm-messages.slin' (language 'de')
[Jul 30 13:58:06] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format ulaw
[Jul 30 13:58:06] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format slin
[Jul 30 13:58:06] VERBOSE[21544] logger.c:     -- <SIP/Proxy_ESN-00000003> Playing 'vm-onefor.slin' (language 'de')
[Jul 30 13:58:07] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format ulaw
[Jul 30 13:58:07] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format slin
[Jul 30 13:58:07] VERBOSE[21544] logger.c:     -- <SIP/Proxy_ESN-00000003> Playing 'vm-INBOX.slin' (language 'de')
[Jul 30 13:58:08] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format ulaw
[Jul 30 13:58:08] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format slin
[Jul 30 13:58:08] VERBOSE[21544] logger.c:     -- <SIP/Proxy_ESN-00000003> Playing 'vm-messages.slin' (language 'de')
[Jul 30 13:58:09] DEBUG[21544] rtp.c: Sending dtmf: 49 (1), at 156.150.133.165
[Jul 30 13:58:09] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format ulaw
[Jul 30 13:58:09] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format slin
[Jul 30 13:58:09] VERBOSE[21544] logger.c:     -- <SIP/Proxy_ESN-00000003> Playing 'vm-opts.slin' (language 'de')
[Jul 30 13:58:09] DEBUG[21544] rtp.c: Sending dtmf: 49 (1), at 156.150.133.165
[Jul 30 13:58:09] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format ulaw
[Jul 30 13:58:09] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format slin
[Jul 30 13:58:09] VERBOSE[21544] logger.c:     -- <SIP/Proxy_ESN-00000003> Playing 'vm-first.slin' (language 'de')
[Jul 30 13:58:10] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format ulaw
[Jul 30 13:58:10] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format slin
[Jul 30 13:58:10] VERBOSE[21544] logger.c:     -- <SIP/Proxy_ESN-00000003> Playing 'vm-message.slin' (language 'de')
[Jul 30 13:58:11] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format ulaw
[Jul 30 13:58:11] VERBOSE[21544] logger.c:   == Parsing '/var/spool/asterisk/voicemail/default/9999/INBOX/Voicemail/msg0000.txt': [Jul 30 13:58:11] DEBUG[21544] config.c: Parsing /var/spool/asterisk/voicemail/default/9999/INBOX/Voicemail/msg0000.txt
[Jul 30 13:58:11] VERBOSE[21544] logger.c:   == Found
[Jul 30 13:58:11] DEBUG[21544] app_voicemail.c: VM-Duration: duration is: 6 seconds converted to: 0 minutes
[Jul 30 13:58:11] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format gsm
[Jul 30 13:58:11] VERBOSE[21544] logger.c:     -- <SIP/Proxy_ESN-00000003> Playing '/var/spool/asterisk/voicemail/default/9999/INBOX/Voicemail/msg0000.gsm' (language 'de')
[Jul 30 13:58:13] DEBUG[21500] chan_sip.c: Allocating new SIP dialog for 5b38575420a8214b76bef96a3a6be40c@156.150.133.165 - OPTIONS (No RTP)
[Jul 30 13:58:13] DEBUG[21500] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 156.150.133.165:5060
[Jul 30 13:58:17] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format ulaw
[Jul 30 13:58:17] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format slin
[Jul 30 13:58:17] VERBOSE[21544] logger.c:     -- <SIP/Proxy_ESN-00000003> Playing 'vm-advopts.slin' (language 'de')
[Jul 30 13:58:19] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format ulaw
[Jul 30 13:58:19] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format slin
[Jul 30 13:58:19] VERBOSE[21544] logger.c:     -- <SIP/Proxy_ESN-00000003> Playing 'vm-repeat.slin' (language 'de')
[Jul 30 13:58:20] DEBUG[21544] rtp.c: Sending dtmf: 55 (7), at 156.150.133.165
[Jul 30 13:58:20] DEBUG[21544] rtp.c: Sending dtmf: 55 (7), at 156.150.133.165
[Jul 30 13:58:20] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format ulaw
[Jul 30 13:58:20] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format slin
[Jul 30 13:58:20] VERBOSE[21544] logger.c:     -- <SIP/Proxy_ESN-00000003> Playing 'vm-deleted.slin' (language 'de')
[Jul 30 13:58:21] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format ulaw
[Jul 30 13:58:21] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format slin
[Jul 30 13:58:21] VERBOSE[21544] logger.c:     -- <SIP/Proxy_ESN-00000003> Playing 'vm-advopts.slin' (language 'de')
[Jul 30 13:58:23] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format ulaw
[Jul 30 13:58:23] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format slin
[Jul 30 13:58:23] VERBOSE[21544] logger.c:     -- <SIP/Proxy_ESN-00000003> Playing 'vm-repeat.slin' (language 'de')
[Jul 30 13:58:26] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format ulaw
[Jul 30 13:58:26] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format slin
[Jul 30 13:58:26] VERBOSE[21544] logger.c:     -- <SIP/Proxy_ESN-00000003> Playing 'vm-next.slin' (language 'de')
[Jul 30 13:58:28] DEBUG[21544] rtp.c: Sending dtmf: 54 (6), at 156.150.133.165
[Jul 30 13:58:28] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format ulaw
[Jul 30 13:58:28] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format slin
[Jul 30 13:58:28] VERBOSE[21544] logger.c:     -- <SIP/Proxy_ESN-00000003> Playing 'vm-undelete.slin' (language 'de')
[Jul 30 13:58:28] DEBUG[21544] rtp.c: Sending dtmf: 54 (6), at 156.150.133.165
[Jul 30 13:58:28] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format ulaw
[Jul 30 13:58:28] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format slin
[Jul 30 13:58:28] VERBOSE[21544] logger.c:     -- <SIP/Proxy_ESN-00000003> Playing 'vm-last.slin' (language 'de')
[Jul 30 13:58:29] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format ulaw
[Jul 30 13:58:29] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format slin
[Jul 30 13:58:29] VERBOSE[21544] logger.c:     -- <SIP/Proxy_ESN-00000003> Playing 'vm-message.slin' (language 'de')
[Jul 30 13:58:30] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format ulaw
[Jul 30 13:58:30] VERBOSE[21544] logger.c:   == Parsing '/var/spool/asterisk/voicemail/default/9999/INBOX/Voicemail/msg0001.txt': [Jul 30 13:58:30] DEBUG[21544] config.c: Parsing /var/spool/asterisk/voicemail/default/9999/INBOX/Voicemail/msg0001.txt
[Jul 30 13:58:30] VERBOSE[21544] logger.c:   == Found
[Jul 30 13:58:30] DEBUG[21544] app_voicemail.c: VM-Duration: duration is: 5 seconds converted to: 0 minutes
[Jul 30 13:58:30] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format gsm
[Jul 30 13:58:30] VERBOSE[21544] logger.c:     -- <SIP/Proxy_ESN-00000003> Playing '/var/spool/asterisk/voicemail/default/9999/INBOX/Voicemail/msg0001.gsm' (language 'de')
[Jul 30 13:58:35] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format ulaw
[Jul 30 13:58:35] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format slin
[Jul 30 13:58:35] VERBOSE[21544] logger.c:     -- <SIP/Proxy_ESN-00000003> Playing 'vm-prev.slin' (language 'de')
[Jul 30 13:58:36] DEBUG[21544] rtp.c: Sending dtmf: 55 (7), at 156.150.133.165
[Jul 30 13:58:37] DEBUG[21544] rtp.c: Sending dtmf: 55 (7), at 156.150.133.165
[Jul 30 13:58:37] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format ulaw
[Jul 30 13:58:37] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format slin
[Jul 30 13:58:37] VERBOSE[21544] logger.c:     -- <SIP/Proxy_ESN-00000003> Playing 'vm-deleted.slin' (language 'de')
[Jul 30 13:58:38] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format ulaw
[Jul 30 13:58:38] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format slin
[Jul 30 13:58:38] VERBOSE[21544] logger.c:     -- <SIP/Proxy_ESN-00000003> Playing 'vm-prev.slin' (language 'de')
[Jul 30 13:58:40] DEBUG[21500] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jul 30 13:58:40] DEBUG[21500] chan_sip.c: Initializing initreq for method OPTIONS - callid 18e6ba756c3c17143b8d05cc1bb7d688@156.150.132.46
[Jul 30 13:58:40] DEBUG[21500] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 156.150.133.165:5060
[Jul 30 13:58:40] DEBUG[21500] chan_sip.c: Stopping retransmission on '18e6ba756c3c17143b8d05cc1bb7d688@156.150.132.46' of Request 102: Match Found
[Jul 30 13:58:40] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format ulaw
[Jul 30 13:58:40] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format slin
[Jul 30 13:58:40] VERBOSE[21544] logger.c:     -- <SIP/Proxy_ESN-00000003> Playing 'vm-advopts.slin' (language 'de')
[Jul 30 13:58:42] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format ulaw
[Jul 30 13:58:42] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format slin
[Jul 30 13:58:42] VERBOSE[21544] logger.c:     -- <SIP/Proxy_ESN-00000003> Playing 'vm-repeat.slin' (language 'de')
[Jul 30 13:58:43] DEBUG[21500] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 156.150.133.165:5060
[Jul 30 13:58:43] WARNING[21544] file.c: Failed to write frame
[Jul 30 13:58:43] DEBUG[21544] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format ulaw
[Jul 30 13:58:43] DEBUG[21544] app_voicemail.c: IMAP Info: EXPUNGE completed.
[Jul 30 13:58:43] ERROR[21544] app_voicemail.c: IMAP Error: The specified message set is invalid.
[Jul 30 13:58:43] DEBUG[21544] app_voicemail.c: IMAP Info: EXPUNGE completed.
[Jul 30 13:58:43] DEBUG[21544] app_voicemail.c: IMAP Info: EXPUNGE completed.
[Jul 30 13:58:43] VERBOSE[21544] logger.c:   == Spawn extension (macro-vm, adef, 1) exited non-zero on 'SIP/Proxy_ESN-00000003' in macro 'vm'
[Jul 30 13:58:43] VERBOSE[21544] logger.c:   == Spawn extension (macro-exten-vm, s, 18) exited non-zero on 'SIP/Proxy_ESN-00000003' in macro 'exten-vm'
[Jul 30 13:58:43] DEBUG[21544] pbx.c: Spawn extension (from-internal,9999,1) exited non-zero on 'SIP/Proxy_ESN-00000003'
[Jul 30 13:58:43] VERBOSE[21544] logger.c:   == Spawn extension (from-internal, 9999, 1) exited non-zero on 'SIP/Proxy_ESN-00000003'
[Jul 30 13:58:43] DEBUG[21544] channel.c: Soft-Hanging up channel 'SIP/Proxy_ESN-00000003'
[Jul 30 13:58:43] DEBUG[21544] pbx.c: Launching 'Macro'
[Jul 30 13:58:43] VERBOSE[21544] logger.c:     -- Executing [h@from-internal:1] Macro("SIP/Proxy_ESN-00000003", "hangupcall") in new stack
[Jul 30 13:58:43] DEBUG[21544] pbx.c: Expression result is '1'
[Jul 30 13:58:43] DEBUG[21544] pbx.c: Launching 'GotoIf'
[Jul 30 13:58:43] VERBOSE[21544] logger.c:     -- Executing [s@macro-hangupcall:1] GotoIf("SIP/Proxy_ESN-00000003", "1?skiprg") in new stack
[Jul 30 13:58:43] VERBOSE[21544] logger.c:     -- Goto (macro-hangupcall,s,4)
[Jul 30 13:58:43] DEBUG[21544] app_macro.c: Executed application: GotoIf
[Jul 30 13:58:43] DEBUG[21544] pbx.c: Expression result is '1'
[Jul 30 13:58:43] DEBUG[21544] pbx.c: Launching 'GotoIf'
[Jul 30 13:58:43] VERBOSE[21544] logger.c:     -- Executing [s@macro-hangupcall:4] GotoIf("SIP/Proxy_ESN-00000003", "1?skipblkvm") in new stack
[Jul 30 13:58:43] VERBOSE[21544] logger.c:     -- Goto (macro-hangupcall,s,7)
[Jul 30 13:58:43] DEBUG[21544] app_macro.c: Executed application: GotoIf
[Jul 30 13:58:43] DEBUG[21544] pbx.c: Expression result is '1'
[Jul 30 13:58:43] DEBUG[21544] pbx.c: Launching 'GotoIf'
[Jul 30 13:58:43] VERBOSE[21544] logger.c:     -- Executing [s@macro-hangupcall:7] GotoIf("SIP/Proxy_ESN-00000003", "1?theend") in new stack
[Jul 30 13:58:43] VERBOSE[21544] logger.c:     -- Goto (macro-hangupcall,s,9)
[Jul 30 13:58:43] DEBUG[21544] app_macro.c: Executed application: GotoIf
[Jul 30 13:58:43] DEBUG[21544] pbx.c: Launching 'Hangup'
[Jul 30 13:58:43] VERBOSE[21544] logger.c:     -- Executing [s@macro-hangupcall:9] Hangup("SIP/Proxy_ESN-00000003", "") in new stack
[Jul 30 13:58:43] VERBOSE[21544] logger.c:   == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'SIP/Proxy_ESN-00000003' in macro 'hangupcall'
[Jul 30 13:58:43] DEBUG[21544] pbx.c: Spawn extension (from-internal,h,1) exited non-zero on 'SIP/Proxy_ESN-00000003'
[Jul 30 13:58:43] VERBOSE[21544] logger.c:   == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/Proxy_ESN-00000003'
[Jul 30 13:58:43] DEBUG[21544] channel.c: Hanging up channel 'SIP/Proxy_ESN-00000003'
[Jul 30 13:58:43] DEBUG[21544] chan_sip.c: Hangup call SIP/Proxy_ESN-00000003, SIP callid 1f4a294a0743d5a659ef22e96f17d56a@156.150.133.165
[Jul 30 13:58:43] DEBUG[21520] manager.c: Manager received command 'MailboxCount'
[Jul 30 13:58:43] WARNING[21520] app_voicemail.c: IMAP Warning: Unknown message data: 1 FETCH
[Jul 30 13:58:43] WARNING[21520] app_voicemail.c: IMAP Warning: Unknown message data: 2 FETCH
[Jul 30 13:58:43] WARNING[21520] app_voicemail.c: IMAP Warning: Unknown message data: 1 EXPUNGE
[Jul 30 13:58:43] DEBUG[21520] app_voicemail.c: IMAP Info: Reusing connection to 156.150.130.20/user="A100670@deuser.de.intra\A100658"
[Jul 30 13:58:43] DEBUG[21520] app_voicemail.c: IMAP Info: Reusing connection to 156.150.130.20/user="A100670@deuser.de.intra\A100658"
[Jul 30 13:58:48] DEBUG[21520] manager.c: Manager received command 'Command'
[Jul 30 13:58:48] DEBUG[21520] manager.c: Manager received command 'Command'
[Jul 30 13:58:48] DEBUG[21520] manager.c: Manager received command 'Command'
[Jul 30 13:58:48] DEBUG[21520] manager.c: Manager received command 'MailboxStatus'
[Jul 30 13:58:48] DEBUG[21520] app_voicemail.c: IMAP Info: Reusing connection to 156.150.130.20/user="A100670@deuser.de.intra\A100658"
[Jul 30 13:58:49] DEBUG[21520] manager.c: Manager received command 'MailboxCount'
[Jul 30 13:58:49] DEBUG[21520] app_voicemail.c: IMAP Info: Reusing connection to 156.150.130.20/user="A100670@deuser.de.intra\A100658"
[Jul 30 13:58:49] DEBUG[21520] app_voicemail.c: IMAP Info: Reusing connection to 156.150.130.20/user="A100670@deuser.de.intra\A100658"
[Jul 30 13:59:13] DEBUG[21500] chan_sip.c: Allocating new SIP dialog for 24abc1817033d8ab5129ac8c61b51abb@156.150.133.165 - OPTIONS (No RTP)
[Jul 30 13:59:13] DEBUG[21500] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 156.150.133.165:5060
[Jul 30 13:59:40] DEBUG[21500] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jul 30 13:59:40] DEBUG[21500] chan_sip.c: Initializing initreq for method OPTIONS - callid 669d07df4e3a8e0313be521a741d6d55@156.150.132.46
[Jul 30 13:59:40] DEBUG[21500] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 156.150.133.165:5060
[Jul 30 13:59:40] DEBUG[21500] chan_sip.c: Stopping retransmission on '669d07df4e3a8e0313be521a741d6d55@156.150.132.46' of Request 102: Match Found
[Jul 30 14:00:13] DEBUG[21500] chan_sip.c: Allocating new SIP dialog for 62689bd50e3d3bb65ca14f244fff2500@156.150.133.165 - OPTIONS (No RTP)
[Jul 30 14:00:13] DEBUG[21500] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 156.150.133.165:5060
[Jul 30 14:00:40] DEBUG[21500] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jul 30 14:00:40] DEBUG[21500] chan_sip.c: Initializing initreq for method OPTIONS - callid 5b5ce1771d00a83718808bfe7d0ebfef@156.150.132.46
[Jul 30 14:00:40] DEBUG[21500] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 156.150.133.165:5060
[Jul 30 14:00:40] DEBUG[21500] chan_sip.c: Stopping retransmission on '5b5ce1771d00a83718808bfe7d0ebfef@156.150.132.46' of Request 102: Match Found
[Jul 30 14:00:48] DEBUG[21520] manager.c: Manager received command 'Command'
[Jul 30 14:00:48] DEBUG[21520] manager.c: Manager received command 'Command'
[Jul 30 14:00:48] DEBUG[21520] manager.c: Manager received command 'Command'
[Jul 30 14:00:48] DEBUG[21520] manager.c: Manager received command 'MailboxStatus'
[Jul 30 14:00:48] DEBUG[21520] app_voicemail.c: IMAP Info: Reusing connection to 156.150.130.20/user="A100670@deuser.de.intra\A100658"
[Jul 30 14:00:49] DEBUG[21520] manager.c: Manager received command 'MailboxCount'
[Jul 30 14:00:49] DEBUG[21520] app_voicemail.c: IMAP Info: Reusing connection to 156.150.130.20/user="A100670@deuser.de.intra\A100658"
[Jul 30 14:00:49] DEBUG[21520] app_voicemail.c: IMAP Info: Reusing connection to 156.150.130.20/user="A100670@deuser.de.intra\A100658"
[Jul 30 14:01:13] DEBUG[21500] chan_sip.c: Allocating new SIP dialog for 192979bb47ec71711aa52fb301146402@156.150.133.165 - OPTIONS (No RTP)
[Jul 30 14:01:13] DEBUG[21500] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 156.150.133.165:5060
[Jul 30 14:01:40] DEBUG[21500] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jul 30 14:01:40] DEBUG[21500] chan_sip.c: Initializing initreq for method OPTIONS - callid 631796ce2499277f4dcd5d9355454ad6@156.150.132.46
[Jul 30 14:01:40] DEBUG[21500] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 156.150.133.165:5060
[Jul 30 14:01:40] DEBUG[21500] chan_sip.c: Stopping retransmission on '631796ce2499277f4dcd5d9355454ad6@156.150.132.46' of Request 102: Match Found
[Jul 30 14:02:13] DEBUG[21500] chan_sip.c: Allocating new SIP dialog for 5024f2795b657bd43da5466467abd114@156.150.133.165 - OPTIONS (No RTP)
[Jul 30 14:02:13] DEBUG[21500] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 156.150.133.165:5060
[Jul 30 14:02:40] DEBUG[21500] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jul 30 14:02:40] DEBUG[21500] chan_sip.c: Initializing initreq for method OPTIONS - callid 288945370246398a3b8559b277f1d79f@156.150.132.46
[Jul 30 14:02:40] DEBUG[21500] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 156.150.133.165:5060
[Jul 30 14:02:40] DEBUG[21500] chan_sip.c: Stopping retransmission on '288945370246398a3b8559b277f1d79f@156.150.132.46' of Request 102: Match Found
[Jul 30 14:02:48] DEBUG[21520] manager.c: Manager received command 'Command'
[Jul 30 14:02:48] DEBUG[21520] manager.c: Manager received command 'Command'
[Jul 30 14:02:48] DEBUG[21520] manager.c: Manager received command 'Command'
[Jul 30 14:02:48] DEBUG[21520] manager.c: Manager received command 'MailboxStatus'
[Jul 30 14:02:48] DEBUG[21520] app_voicemail.c: IMAP Info: Reusing connection to 156.150.130.20/user="A100670@deuser.de.intra\A100658"
[Jul 30 14:02:49] DEBUG[21520] manager.c: Manager received command 'MailboxCount'
[Jul 30 14:02:49] DEBUG[21520] app_voicemail.c: IMAP Info: Reusing connection to 156.150.130.20/user="A100670@deuser.de.intra\A100658"
[Jul 30 14:02:49] DEBUG[21520] app_voicemail.c: IMAP Info: Reusing connection to 156.150.130.20/user="A100670@deuser.de.intra\A100658"
[Jul 30 14:03:13] DEBUG[21500] chan_sip.c: Allocating new SIP dialog for 03da903e1e4b60013d64afaf2decc14c@156.150.133.165 - OPTIONS (No RTP)
[Jul 30 14:03:13] DEBUG[21500] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 156.150.133.165:5060
[Jul 30 14:03:40] DEBUG[21500] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jul 30 14:03:40] DEBUG[21500] chan_sip.c: Initializing initreq for method OPTIONS - callid 11ae453b5009228009507fef410eb381@156.150.132.46
[Jul 30 14:03:40] DEBUG[21500] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 156.150.133.165:5060
[Jul 30 14:03:40] DEBUG[21500] chan_sip.c: Stopping retransmission on '11ae453b5009228009507fef410eb381@156.150.132.46' of Request 102: Match Found
[Jul 30 14:04:13] DEBUG[21500] chan_sip.c: Allocating new SIP dialog for 28654da2230dbddc3ee258696a1333a7@156.150.133.165 - OPTIONS (No RTP)
[Jul 30 14:04:13] DEBUG[21500] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 156.150.133.165:5060
[Jul 30 14:04:40] DEBUG[21500] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jul 30 14:04:40] DEBUG[21500] chan_sip.c: Initializing initreq for method OPTIONS - callid 3972fb247c283f8e674991187649f1b1@156.150.132.46
[Jul 30 14:04:40] DEBUG[21500] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 156.150.133.165:5060
[Jul 30 14:04:40] DEBUG[21500] chan_sip.c: Stopping retransmission on '3972fb247c283f8e674991187649f1b1@156.150.132.46' of Request 102: Match Found
[Jul 30 14:04:48] DEBUG[21520] manager.c: Manager received command 'Command'
[Jul 30 14:04:48] DEBUG[21520] manager.c: Manager received command 'Command'
[Jul 30 14:04:48] DEBUG[21520] manager.c: Manager received command 'Command'
[Jul 30 14:04:48] DEBUG[21520] manager.c: Manager received command 'MailboxStatus'
[Jul 30 14:04:48] DEBUG[21520] app_voicemail.c: IMAP Info: Reusing connection to 156.150.130.20/user="A100670@deuser.de.intra\A100658"
[Jul 30 14:04:49] DEBUG[21520] manager.c: Manager received command 'MailboxCount'
[Jul 30 14:04:49] DEBUG[21520] app_voicemail.c: IMAP Info: Reusing connection to 156.150.130.20/user="A100670@deuser.de.intra\A100658"
[Jul 30 14:04:49] DEBUG[21520] app_voicemail.c: IMAP Info: Reusing connection to 156.150.130.20/user="A100670@deuser.de.intra\A100658"
[Jul 30 14:05:13] DEBUG[21500] chan_sip.c: Allocating new SIP dialog for 23889e103eddbef86fc8bdbf7f9ef596@156.150.133.165 - OPTIONS (No RTP)
[Jul 30 14:05:13] DEBUG[21500] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 156.150.133.165:5060
A