[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: After vm_authenticate
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: comparing mailbox 9999@default (i=0) to vmstate mailbox 9999@default (i=0)
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: Found it!
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: Duplicate mailbox 9999, copying message info...
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: Before open_mailbox
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: Before init_mailstream, user is A100670@deuser.de.intra\A100670
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: vm_state user is:A100670@deuser.de.intra\A100670
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: mailstream not set.
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: Before mail_open, server: {156.150.130.20:143/imap/user=A100670@deuser.de.intra\A100670}INBOX/Voicemail, box:1
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: IMAP Info: Trying IP address [156.150.130.20]
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: Entering NOTIFY callback, errflag is 0, string is Microsoft Exchange Server 2003 IMAP4rev1 server version 6.5.7638.1 (DEESX001.deuser.de.intra) ready.
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: IMAP Info: Microsoft Exchange Server 2003 IMAP4rev1 server version 6.5.7638.1 (DEESX001.deuser.de.intra) ready.
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: Entering callback mm_login
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: Entering EXISTS callback for message 1
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: A100670@deuser.de.intra\A100670}INBOX not found in vmstates
[Aug 10 16:08:59] WARNING[3618] app_voicemail.c: User A100670@deuser.de.intra\A100670}INBOX mailbox not found for update.
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: Entering NOTIFY callback, errflag is 0, string is [UNSEEN 1] Is the first unseen message
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: IMAP Info: [UNSEEN 1] Is the first unseen message
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: Before mail_search_full, user is A100670@deuser.de.intra\A100670
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: Number of old messages: 0
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: Before init_mailstream, user is A100670@deuser.de.intra\A100670
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: vm_state user is:A100670@deuser.de.intra\A100670
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: Before mail_open, server: {156.150.130.20:143/imap/user=A100670@deuser.de.intra\A100670}INBOX/Voicemail, box:0
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: IMAP Info: Reusing connection to 156.150.130.20/user="A100670@deuser.de.intra\A100670"
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: Entering EXISTS callback for message 1
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: A100670@deuser.de.intra\A100670}INBOX not found in vmstates
[Aug 10 16:08:59] WARNING[3618] app_voicemail.c: User A100670@deuser.de.intra\A100670}INBOX mailbox not found for update.
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: Entering NOTIFY callback, errflag is 0, string is [UNSEEN 1] Is the first unseen message
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: IMAP Info: [UNSEEN 1] Is the first unseen message
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: Mailbox name set to: INBOX/Voicemail, about to check quotas
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: Mailbox name set to: INBOX/Voicemail, about to check quotas
[Aug 10 16:08:59] ERROR[3618] app_voicemail.c: IMAP Error: Quota not available on this IMAP server
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: Before mail_search_full, user is A100670@deuser.de.intra\A100670
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: saving mailbox message number 1 as message 0. Interactive set to 1
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: Entering FLAGS callback for message 1
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: User A100670@deuser.de.intra\A100670 mailbox set for update.
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: Number of new messages: 1
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: Before init_mailstream, user is A100670@deuser.de.intra\A100670
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: vm_state user is:A100670@deuser.de.intra\A100670
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: Before mail_open, server: {156.150.130.20:143/imap/user=A100670@deuser.de.intra\A100670}INBOX/Voicemail, box:0
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: IMAP Info: Reusing connection to 156.150.130.20/user="A100670@deuser.de.intra\A100670"
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: Entering EXISTS callback for message 1
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: A100670@deuser.de.intra\A100670}INBOX not found in vmstates
[Aug 10 16:08:59] WARNING[3618] app_voicemail.c: User A100670@deuser.de.intra\A100670}INBOX mailbox not found for update.
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: Entering NOTIFY callback, errflag is 0, string is [UNSEEN 1] Is the first unseen message
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: IMAP Info: [UNSEEN 1] Is the first unseen message
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: Mailbox name set to: INBOX/Voicemail, about to check quotas
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: Mailbox name set to: INBOX/Voicemail, about to check quotas
[Aug 10 16:08:59] ERROR[3618] app_voicemail.c: IMAP Error: Quota not available on this IMAP server
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: Before mail_search_full, user is A100670@deuser.de.intra\A100670
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: Number of urgent messages: 0
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: Before init_mailstream, user is A100670@deuser.de.intra\A100670
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: vm_state user is:A100670@deuser.de.intra\A100670
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: Before mail_open, server: {156.150.130.20:143/imap/user=A100670@deuser.de.intra\A100670}INBOX/Voicemail, box:0
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: IMAP Info: Reusing connection to 156.150.130.20/user="A100670@deuser.de.intra\A100670"
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: Entering EXISTS callback for message 1
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: A100670@deuser.de.intra\A100670}INBOX not found in vmstates
[Aug 10 16:08:59] WARNING[3618] app_voicemail.c: User A100670@deuser.de.intra\A100670}INBOX mailbox not found for update.
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: Entering NOTIFY callback, errflag is 0, string is [UNSEEN 1] Is the first unseen message
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: IMAP Info: [UNSEEN 1] Is the first unseen message
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: Mailbox name set to: INBOX/Voicemail, about to check quotas
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: Mailbox name set to: INBOX/Voicemail, about to check quotas
[Aug 10 16:08:59] ERROR[3618] app_voicemail.c: IMAP Error: Quota not available on this IMAP server
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: Before mail_search_full, user is A100670@deuser.de.intra\A100670
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: saving mailbox message number 1 as message 0. Interactive set to 1
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: Entering FLAGS callback for message 1
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: User A100670@deuser.de.intra\A100670 mailbox set for update.
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: Checking quotas: comparing 0 to 0
[Aug 10 16:08:59] DEBUG[3618] app_voicemail.c: Checking quotas: User has 1 messages and limit is 100.
[Aug 10 16:08:59] DEBUG[3618] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format slin
[Aug 10 16:08:59] DEBUG[3618] rtp.c: Difference is 27120, ms is 3410
[Aug 10 16:08:59] DEBUG[3618] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Aug 10 16:08:59] VERBOSE[3618] file.c:     -- <SIP/Proxy_ESN-00000003> Playing 'vm-youhave.slin' (language 'de')
[Aug 10 16:08:59] DEBUG[3618] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[Aug 10 16:08:59] DEBUG[3618] rtp.c: - RTP 2833 Event: 0000000b (len = 4)
[Aug 10 16:09:00] DEBUG[3618] channel.c: Scheduling timer at (68 requested / 68 actual) timer ticks per second
[Aug 10 16:09:00] DEBUG[3618] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Aug 10 16:09:00] DEBUG[3618] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Aug 10 16:09:00] DEBUG[3618] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Aug 10 16:09:00] DEBUG[3618] channel.c: Set channel SIP/Proxy_ESN-00000003 to write format ulaw
[Aug 10 16:09:00] WARNING[3618] file.c: File digits/1F does not exist in any format
[Aug 10 16:09:00] WARNING[3618] file.c: Unable to open digits/1F (format 0x280008 (alaw|h263|h264)): No such file or directory
[Aug 10 16:09:00] DEBUG[3618] app_voicemail.c: Returning before search - user is logged in
[Aug 10 16:09:00] DEBUG[3618] app_voicemail.c: Mailbox is set to 9999@default
[Aug 10 16:09:00] DEBUG[3618] app_voicemail.c: Returning before search - user is logged in
[Aug 10 16:09:00] DEBUG[3618] app_voicemail.c: Returning before search - user is logged in
[Aug 10 16:09:00] DEBUG[3618] app_voicemail.c: Returning before search - user is logged in
[Aug 10 16:09:00] DEBUG[3618] app_voicemail.c: *** Checking if we can expunge, deleted set to 0, expungeonhangup set to 1
[Aug 10 16:09:00] DEBUG[3618] app_voicemail.c: Duplicate mailbox 9999, copying message info...
[Aug 10 16:09:00] DEBUG[3618] app_voicemail.c: Entering NOTIFY callback, errflag is 4, string is Microsoft Exchange Server 2003 IMAP4rev1 server version 6.5.7638.1 signing off.
[Aug 10 16:09:00] DEBUG[3618] app_macro.c: Spawn extension (macro-vm,adef,1) exited non-zero on 'SIP/Proxy_ESN-00000003' in macro 'vm'
[Aug 10 16:09:00] VERBOSE[3618] app_macro.c:   == Spawn extension (macro-vm, adef, 1) exited non-zero on 'SIP/Proxy_ESN-00000003' in macro 'vm'
[Aug 10 16:09:00] DEBUG[3618] app_macro.c: Spawn extension (macro-exten-vm,s,18) exited non-zero on 'SIP/Proxy_ESN-00000003' in macro 'exten-vm'
[Aug 10 16:09:00] VERBOSE[3618] app_macro.c:   == Spawn extension (macro-exten-vm, s, 18) exited non-zero on 'SIP/Proxy_ESN-00000003' in macro 'exten-vm'
[Aug 10 16:09:00] DEBUG[3618] pbx.c: Spawn extension (from-internal,9999,1) exited non-zero on 'SIP/Proxy_ESN-00000003'
[Aug 10 16:09:00] VERBOSE[3618] pbx.c:   == Spawn extension (from-internal, 9999, 1) exited non-zero on 'SIP/Proxy_ESN-00000003'
[Aug 10 16:09:00] DEBUG[3618] channel.c: Soft-Hanging up channel 'SIP/Proxy_ESN-00000003'
[Aug 10 16:09:00] DEBUG[3618] pbx.c: Launching 'Macro'
[Aug 10 16:09:00] VERBOSE[3618] pbx.c:     -- Executing [h@from-internal:1] Macro("SIP/Proxy_ESN-00000003", "hangupcall") in new stack
[Aug 10 16:09:00] DEBUG[3618] pbx.c: Expression result is '1'
[Aug 10 16:09:00] DEBUG[3618] pbx.c: Launching 'GotoIf'
[Aug 10 16:09:00] VERBOSE[3618] pbx.c:     -- Executing [s@macro-hangupcall:1] GotoIf("SIP/Proxy_ESN-00000003", "1?skiprg") in new stack
[Aug 10 16:09:00] VERBOSE[3618] pbx.c:     -- Goto (macro-hangupcall,s,4)
[Aug 10 16:09:00] DEBUG[3618] app_macro.c: Executed application: GotoIf
[Aug 10 16:09:00] DEBUG[3618] pbx.c: Expression result is '1'
[Aug 10 16:09:00] DEBUG[3618] pbx.c: Launching 'GotoIf'
[Aug 10 16:09:00] VERBOSE[3618] pbx.c:     -- Executing [s@macro-hangupcall:4] GotoIf("SIP/Proxy_ESN-00000003", "1?skipblkvm") in new stack
[Aug 10 16:09:00] VERBOSE[3618] pbx.c:     -- Goto (macro-hangupcall,s,7)
[Aug 10 16:09:00] DEBUG[3618] app_macro.c: Executed application: GotoIf
[Aug 10 16:09:00] DEBUG[3618] pbx.c: Expression result is '1'
[Aug 10 16:09:00] DEBUG[3618] pbx.c: Launching 'GotoIf'
[Aug 10 16:09:00] VERBOSE[3618] pbx.c:     -- Executing [s@macro-hangupcall:7] GotoIf("SIP/Proxy_ESN-00000003", "1?theend") in new stack
[Aug 10 16:09:00] VERBOSE[3618] pbx.c:     -- Goto (macro-hangupcall,s,9)
[Aug 10 16:09:00] DEBUG[3618] app_macro.c: Executed application: GotoIf
[Aug 10 16:09:00] DEBUG[3618] pbx.c: Launching 'Hangup'
[Aug 10 16:09:00] VERBOSE[3618] pbx.c:     -- Executing [s@macro-hangupcall:9] Hangup("SIP/Proxy_ESN-00000003", "") in new stack
[Aug 10 16:09:00] DEBUG[3618] app_macro.c: Spawn extension (macro-hangupcall,s,9) exited non-zero on 'SIP/Proxy_ESN-00000003' in macro 'hangupcall'
[Aug 10 16:09:00] VERBOSE[3618] app_macro.c:   == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'SIP/Proxy_ESN-00000003' in macro 'hangupcall'
[Aug 10 16:09:00] DEBUG[3618] pbx.c: Spawn extension (from-internal,h,1) exited non-zero on 'SIP/Proxy_ESN-00000003'
[Aug 10 16:09:00] VERBOSE[3618] pbx.c:   == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/Proxy_ESN-00000003'
[Aug 10 16:09:00] DEBUG[3618] channel.c: Hanging up channel 'SIP/Proxy_ESN-00000003'
[Aug 10 16:09:00] DEBUG[3618] chan_sip.c: Hangup call SIP/Proxy_ESN-00000003, SIP callid 1cae0a9c445c887476a3a8f64763474a@156.150.133.165
[Aug 10 16:09:00] DEBUG[3618] chan_sip.c: Session timer stopped: -1 - 1cae0a9c445c887476a3a8f64763474a@156.150.133.165
[Aug 10 16:09:00] DEBUG[3618] chan_sip.c: Trying to put 'BYE sip:008' onto UDP socket destined for 156.150.133.165:5060
[Aug 10 16:09:00] DEBUG[3326] chan_sip.c: Stopping retransmission on '1cae0a9c445c887476a3a8f64763474a@156.150.133.165' of Request 102: Match Found
[Aug 10 16:09:00] DEBUG[3326] chan_sip.c: Destroying SIP dialog 1cae0a9c445c887476a3a8f64763474a@156.150.133.165
[Aug 10 16:09:00] DEBUG[3618] cdr.c: Dropping CDR !
[Aug 10 16:09:00] DEBUG[3312] devicestate.c: No provider found, checking channel drivers for SIP - Proxy_ESN
[Aug 10 16:09:00] DEBUG[3312] chan_sip.c: Checking device state for peer Proxy_ESN
[Aug 10 16:09:00] DEBUG[3312] devicestate.c: Changing state for SIP/Proxy_ESN - state 1 (Not in use)
[Aug 10 16:09:00] DEBUG[3312] devicestate.c: device 'SIP/Proxy_ESN' state '1'
[Aug 10 16:09:00] DEBUG[3394] app_queue.c: Device 'SIP/Proxy_ESN' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Aug 10 16:09:00] DEBUG[3598] manager.c: Manager received command 'MailboxCount'
[Aug 10 16:09:00] DEBUG[3598] app_voicemail.c: Mailbox is set to 9999@default
[Aug 10 16:09:00] DEBUG[3598] app_voicemail.c: vm_state user is:A100670@deuser.de.intra\A100670
[Aug 10 16:09:00] DEBUG[3598] app_voicemail.c: Before mail_open, server: {156.150.130.20:143/imap/user=A100670@deuser.de.intra\A100670}INBOX/Voicemail, box:0
[Aug 10 16:09:00] DEBUG[3598] app_voicemail.c: IMAP Info: Reusing connection to 156.150.130.20/user="A100670@deuser.de.intra\A100670"
[Aug 10 16:09:00] DEBUG[3598] app_voicemail.c: Entering EXISTS callback for message 1
[Aug 10 16:09:00] DEBUG[3598] app_voicemail.c: A100670@deuser.de.intra\A100670}INBOX not found in vmstates
[Aug 10 16:09:00] WARNING[3598] app_voicemail.c: User A100670@deuser.de.intra\A100670}INBOX mailbox not found for update.
[Aug 10 16:09:00] DEBUG[3598] app_voicemail.c: Entering NOTIFY callback, errflag is 0, string is [UNSEEN 1] Is the first unseen message
[Aug 10 16:09:00] DEBUG[3598] app_voicemail.c: IMAP Info: [UNSEEN 1] Is the first unseen message
[Aug 10 16:09:00] DEBUG[3598] app_voicemail.c: saving mailbox message number 1 as message 0. Interactive set to 0
[Aug 10 16:09:00] DEBUG[3598] app_voicemail.c: Entering FLAGS callback for message 1
[Aug 10 16:09:00] DEBUG[3598] app_voicemail.c: User A100670@deuser.de.intra\A100670 mailbox set for update.
[Aug 10 16:09:00] DEBUG[3598] app_voicemail.c: vm_state user is:A100670@deuser.de.intra\A100670
[Aug 10 16:09:00] DEBUG[3598] app_voicemail.c: Before mail_open, server: {156.150.130.20:143/imap/user=A100670@deuser.de.intra\A100670}INBOX/Voicemail, box:1
[Aug 10 16:09:00] DEBUG[3598] app_voicemail.c: IMAP Info: Reusing connection to 156.150.130.20/user="A100670@deuser.de.intra\A100670"
[Aug 10 16:09:00] DEBUG[3598] app_voicemail.c: Entering EXISTS callback for message 1
[Aug 10 16:09:00] DEBUG[3598] app_voicemail.c: A100670@deuser.de.intra\A100670}INBOX not found in vmstates
[Aug 10 16:09:00] WARNING[3598] app_voicemail.c: User A100670@deuser.de.intra\A100670}INBOX mailbox not found for update.
[Aug 10 16:09:00] DEBUG[3598] app_voicemail.c: Entering NOTIFY callback, errflag is 0, string is [UNSEEN 1] Is the first unseen message
[Aug 10 16:09:00] DEBUG[3598] app_voicemail.c: IMAP Info: [UNSEEN 1] Is the first unseen message
[Aug 10 16:09:00] DEBUG[3598] app_voicemail.c: vm_state user is:A100670@deuser.de.intra\A100670
[Aug 10 16:09:00] DEBUG[3598] app_voicemail.c: Before mail_open, server: {156.150.130.20:143/imap/user=A100670@deuser.de.intra\A100670}INBOX/Voicemail, box:0
[Aug 10 16:09:00] DEBUG[3598] app_voicemail.c: IMAP Info: Reusing connection to 156.150.130.20/user="A100670@deuser.de.intra\A100670"
[Aug 10 16:09:00] DEBUG[3598] app_voicemail.c: Entering EXISTS callback for message 1
[Aug 10 16:09:00] DEBUG[3598] app_voicemail.c: A100670@deuser.de.intra\A100670}INBOX not found in vmstates
[Aug 10 16:09:00] WARNING[3598] app_voicemail.c: User A100670@deuser.de.intra\A100670}INBOX mailbox not found for update.
[Aug 10 16:09:00] DEBUG[3598] app_voicemail.c: Entering NOTIFY callback, errflag is 0, string is [UNSEEN 1] Is the first unseen message
[Aug 10 16:09:00] DEBUG[3598] app_voicemail.c: IMAP Info: [UNSEEN 1] Is the first unseen message