[May 25 14:59:05] Asterisk 1.4.4, Copyright (C) 1999 - 2006 Digium, Inc. and others. [May 25 14:59:05] Created by Mark Spencer [May 25 14:59:05] Asterisk comes with ABSOLUTELY NO WARRANTY; type 'core show warranty' for details. [May 25 14:59:05] This is free software, with components licensed under the GNU General Public [May 25 14:59:05] License version 2 and other licenses; you are welcome to redistribute it under [May 25 14:59:05] certain conditions. Type 'core show license' for details. [May 25 14:59:05] ========================================================================= [May 25 14:59:22] DEBUG[3050]: chan_sip.c:3806 sip_new: *** Our native formats are 0x4 (ulaw) [May 25 14:59:22] DEBUG[3050]: chan_sip.c:3807 sip_new: *** Joint capabilities are 0xc (ulaw|alaw) [May 25 14:59:22] DEBUG[3050]: chan_sip.c:3808 sip_new: *** Our capabilities are 0xe (gsm|ulaw|alaw) [May 25 14:59:22] DEBUG[3050]: chan_sip.c:3809 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [May 25 14:59:22] DEBUG[3050]: chan_sip.c:3832 sip_new: This channel will not be able to handle video. [May 25 14:59:22] DEBUG[3050]: chan_sip.c:7994 build_route: build_route: Contact hop: [May 25 14:59:22] DEBUG[3050]: chan_sip.c:13492 handle_request_invite: SIP/2400-08205710: New call is still down.... Trying... [May 25 14:59:22] DEBUG[3050]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/2400-08205710 [May 25 14:59:22] DEBUG[3034]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 2400 [May 25 14:59:22] DEBUG[3034]: chan_sip.c:15321 sip_devicestate: Checking device state for peer 2400 [May 25 14:59:22] DEBUG[3052]: pbx.c:1809 pbx_extension_helper: Launching 'Macro' [May 25 14:59:22] -- Executing [2500@sip-internal:1] Macro("SIP/2400-08205710", "stdexten|2500|SIP/2500") in new stack [May 25 14:59:22] DEBUG[3052]: pbx.c:1809 pbx_extension_helper: Launching 'Dial' [May 25 14:59:22] -- Executing [s@macro-stdexten:1] Dial("SIP/2400-08205710", "SIP/2500|20") in new stack [May 25 14:59:22] DEBUG[3052]: chan_sip.c:15387 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [May 25 14:59:22] DEBUG[3052]: chan_sip.c:4312 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [May 25 14:59:22] DEBUG[3034]: chan_sip.c:7646 reg_source_db: SIP Seeding peer from astdb: '2400' at 2400@192.168.2.27:5060 for 3600 [May 25 14:59:22] DEBUG[3034]: chan_sip.c:2360 sip_destroy_peer: Destroying SIP peer 2400 [May 25 14:59:22] DEBUG[3034]: devicestate.c:287 do_state_change: Changing state for SIP/2400 - state 1 (Not in use) [May 25 14:59:22] DEBUG[3052]: chan_sip.c:7646 reg_source_db: SIP Seeding peer from astdb: '2500' at 2500@192.168.2.20:5060 for 3600 [May 25 14:59:22] DEBUG[3052]: chan_sip.c:2576 do_setnat: Setting NAT on RTP to Off [May 25 14:59:22] DEBUG[3052]: chan_sip.c:2360 sip_destroy_peer: Destroying SIP peer 2500 [May 25 14:59:22] DEBUG[3052]: chan_sip.c:3806 sip_new: *** Our native formats are 0x4 (ulaw) [May 25 14:59:22] DEBUG[3052]: chan_sip.c:3807 sip_new: *** Joint capabilities are 0x0 (nothing) [May 25 14:59:22] DEBUG[3052]: chan_sip.c:3808 sip_new: *** Our capabilities are 0xe (gsm|ulaw|alaw) [May 25 14:59:22] DEBUG[3052]: chan_sip.c:3809 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [May 25 14:59:22] DEBUG[3052]: chan_sip.c:3811 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [May 25 14:59:22] DEBUG[3052]: chan_sip.c:3832 sip_new: This channel will not be able to handle video. [May 25 14:59:22] DEBUG[3052]: channel.c:3376 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-s-1. [May 25 14:59:22] DEBUG[3052]: channel.c:3376 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH. [May 25 14:59:22] DEBUG[3052]: channel.c:3376 ast_channel_inherit_variables: Not copying variable ARG2. [May 25 14:59:22] DEBUG[3052]: channel.c:3376 ast_channel_inherit_variables: Not copying variable ARG1. [May 25 14:59:22] DEBUG[3052]: channel.c:3376 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY. [May 25 14:59:22] DEBUG[3052]: channel.c:3376 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT. [May 25 14:59:22] DEBUG[3052]: channel.c:3376 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN. [May 25 14:59:22] DEBUG[3052]: channel.c:3376 ast_channel_inherit_variables: Not copying variable STACK-sip-internal-2500-1. [May 25 14:59:22] DEBUG[3052]: channel.c:3376 ast_channel_inherit_variables: Not copying variable SIPCALLID. [May 25 14:59:22] DEBUG[3052]: channel.c:3376 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [May 25 14:59:22] DEBUG[3052]: channel.c:3376 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [May 25 14:59:22] DEBUG[3052]: channel.c:3376 ast_channel_inherit_variables: Not copying variable SIPURI. [May 25 14:59:22] DEBUG[3052]: chan_sip.c:2831 sip_call: Outgoing Call for 2500 [May 25 14:59:22] DEBUG[3052]: chan_sip.c:3004 update_call_counter: Updating call counter for outgoing call [May 25 14:59:22] DEBUG[3052]: chan_sip.c:2846 sip_call: Our T38 capability (0), joint T38 capability (0) [May 25 14:59:22] DEBUG[3052]: chan_sip.c:6198 add_sdp: ** Our capability: 0xe (gsm|ulaw|alaw) Video flag: False [May 25 14:59:22] DEBUG[3052]: chan_sip.c:6199 add_sdp: ** Our prefcodec: 0x4 (ulaw) [May 25 14:59:22] DEBUG[3052]: chan_sip.c:6330 add_sdp: -- Done with adding codecs to SDP [May 25 14:59:22] DEBUG[3052]: channel.c:2447 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=26) [May 25 14:59:22] DEBUG[3052]: chan_sip.c:6375 add_sdp: Done building SDP. Settling with this capability: 0xe (gsm|ulaw|alaw) [May 25 14:59:22] -- Called 2500 [May 25 14:59:22] DEBUG[3050]: chan_sip.c:4365 find_call: = Found Their Call ID: 7df6be253e0202107391ea4779b560bc@192.168.2.150 Their Tag Our tag: as69f6b08b [May 25 14:59:22] DEBUG[3050]: chan_sip.c:2132 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '7df6be253e0202107391ea4779b560bc@192.168.2.150' Request 102: Found [May 25 14:59:22] DEBUG[3050]: chan_sip.c:11658 handle_response_invite: SIP response 100 to standard invite [May 25 14:59:22] DEBUG[3050]: chan_sip.c:4365 find_call: = Found Their Call ID: 7df6be253e0202107391ea4779b560bc@192.168.2.150 Their Tag 2FCCC0CC-2955CB0B Our tag: as69f6b08b [May 25 14:59:22] DEBUG[3050]: chan_sip.c:2072 __sip_ack: Acked pending invite 102 [May 25 14:59:22] DEBUG[3050]: chan_sip.c:2090 __sip_ack: Stopping retransmission on '7df6be253e0202107391ea4779b560bc@192.168.2.150' of Request 102: Match Not Found [May 25 14:59:22] -- Got SIP response 486 "Busy Here" back from 192.168.2.20 [May 25 14:59:22] DEBUG[3050]: chan_sip.c:1634 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 7df6be253e0202107391ea4779b560bc@192.168.2.150 [May 25 14:59:22] -- SIP/2500-b7b1af88 is busy [May 25 14:59:22] DEBUG[3052]: channel.c:1726 ast_hangup: Hanging up channel 'SIP/2500-b7b1af88' [May 25 14:59:22] DEBUG[3052]: chan_sip.c:3313 sip_hangup: Hangup call SIP/2500-b7b1af88, SIP callid 7df6be253e0202107391ea4779b560bc@192.168.2.150) [May 25 14:59:22] DEBUG[3052]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/2500-b7b1af88 [May 25 14:59:22] DEBUG[3034]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 2500 [May 25 14:59:22] DEBUG[3034]: chan_sip.c:15321 sip_devicestate: Checking device state for peer 2500 [May 25 14:59:22] DEBUG[3034]: chan_sip.c:7646 reg_source_db: SIP Seeding peer from astdb: '2500' at 2500@192.168.2.20:5060 for 3600 [May 25 14:59:22] DEBUG[3034]: chan_sip.c:2360 sip_destroy_peer: Destroying SIP peer 2500 [May 25 14:59:22] DEBUG[3034]: devicestate.c:287 do_state_change: Changing state for SIP/2500 - state 1 (Not in use) [May 25 14:59:22] == Everyone is busy/congested at this time (1:1/0/0) [May 25 14:59:22] DEBUG[3052]: rtp.c:1476 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [May 25 14:59:22] DEBUG[3052]: app_dial.c:1679 dial_exec_full: Exiting with DIALSTATUS=BUSY. [May 25 14:59:22] DEBUG[3052]: app_macro.c:320 _macro_exec: Executed application: Dial [May 25 14:59:22] DEBUG[3052]: pbx.c:1809 pbx_extension_helper: Launching 'Goto' [May 25 14:59:22] -- Executing [s@macro-stdexten:2] Goto("SIP/2400-08205710", "s-BUSY|1") in new stack [May 25 14:59:22] -- Goto (macro-stdexten,s-BUSY,1) [May 25 14:59:22] DEBUG[3052]: app_macro.c:320 _macro_exec: Executed application: Goto [May 25 14:59:22] DEBUG[3052]: pbx.c:1809 pbx_extension_helper: Launching 'VoiceMail' [May 25 14:59:22] -- Executing [s-BUSY@macro-stdexten:1] VoiceMail("SIP/2400-08205710", "2500|b") in new stack [May 25 14:59:22] DEBUG[3052]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/2400-08205710 [May 25 14:59:22] DEBUG[3034]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 2400 [May 25 14:59:22] DEBUG[3034]: chan_sip.c:15321 sip_devicestate: Checking device state for peer 2400 [May 25 14:59:22] DEBUG[3034]: chan_sip.c:7646 reg_source_db: SIP Seeding peer from astdb: '2400' at 2400@192.168.2.27:5060 for 3600 [May 25 14:59:22] DEBUG[3034]: chan_sip.c:2360 sip_destroy_peer: Destroying SIP peer 2400 [May 25 14:59:22] DEBUG[3034]: devicestate.c:287 do_state_change: Changing state for SIP/2400 - state 1 (Not in use) [May 25 14:59:22] DEBUG[3052]: chan_sip.c:3464 sip_answer: SIP answering channel: SIP/2400-08205710 [May 25 14:59:22] DEBUG[3052]: chan_sip.c:6432 transmit_response_with_sdp: Setting framing from config on incoming call [May 25 14:59:22] DEBUG[3052]: chan_sip.c:6198 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: True [May 25 14:59:22] DEBUG[3052]: chan_sip.c:6199 add_sdp: ** Our prefcodec: 0x0 (nothing) [May 25 14:59:22] DEBUG[3052]: chan_sip.c:6330 add_sdp: -- Done with adding codecs to SDP [May 25 14:59:22] DEBUG[3052]: channel.c:2447 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [May 25 14:59:22] DEBUG[3052]: chan_sip.c:6375 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) [May 25 14:59:22] DEBUG[3052]: app_voicemail.c:2859 leave_voicemail: Before find_user [May 25 14:59:22] DEBUG[3050]: chan_sip.c:4365 find_call: = No match Their Call ID: 7df6be253e0202107391ea4779b560bc@192.168.2.150 Their Tag 2FCCC0CC-2955CB0B Our tag: as69f6b08b [May 25 14:59:22] DEBUG[3050]: chan_sip.c:4365 find_call: = Found Their Call ID: a915f1b8-26735276-77f1ecab@192.168.2.27 Their Tag ADE7B794-187943D9 Our tag: as4788c128 [May 25 14:59:22] DEBUG[3050]: chan_sip.c:14709 handle_request: **** Received ACK (6) - Command in SIP ACK [May 25 14:59:22] DEBUG[3050]: chan_sip.c:2090 __sip_ack: Stopping retransmission on 'a915f1b8-26735276-77f1ecab@192.168.2.27' of Response 2: Match Not Found [May 25 14:59:22] Really destroying SIP dialog '7df6be253e0202107391ea4779b560bc@192.168.2.150' Method: INVITE [May 25 14:59:22] DEBUG[3052]: channel.c:2911 set_format: Set channel SIP/2400-08205710 to write format slin [May 25 14:59:22] DEBUG[3052]: rtp.c:2701 ast_rtp_write: Ooh, format changed from unknown to ulaw [May 25 14:59:22] DEBUG[3052]: rtp.c:2718 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [May 25 14:59:22] DEBUG[3052]: channel.c:2030 ast_settimeout: Scheduling timer at 160 sample intervals [May 25 14:59:22] -- Playing '/var/spool/asterisk/voicemail/default/2500/temp' (language 'fr') [May 25 14:59:27] DEBUG[3052]: channel.c:2030 ast_settimeout: Scheduling timer at 138 sample intervals [May 25 14:59:27] DEBUG[3052]: channel.c:2030 ast_settimeout: Scheduling timer at 0 sample intervals [May 25 14:59:27] DEBUG[3052]: channel.c:2030 ast_settimeout: Scheduling timer at 0 sample intervals [May 25 14:59:27] DEBUG[3052]: channel.c:2911 set_format: Set channel SIP/2400-08205710 to write format ulaw [May 25 14:59:27] DEBUG[3052]: channel.c:2030 ast_settimeout: Scheduling timer at 160 sample intervals [May 25 14:59:27] -- Playing 'vm-intro' (language 'fr') [May 25 14:59:30] DEBUG[3052]: rtp.c:875 ast_rtcp_read: Got RTCP report of 76 bytes [May 25 14:59:34] DEBUG[3052]: channel.c:2030 ast_settimeout: Scheduling timer at 103 sample intervals [May 25 14:59:34] DEBUG[3052]: channel.c:2030 ast_settimeout: Scheduling timer at 0 sample intervals [May 25 14:59:34] DEBUG[3052]: channel.c:2030 ast_settimeout: Scheduling timer at 0 sample intervals [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8719 get_vm_state_by_mailbox: Mailbox set to 2500 [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8741 get_vm_state_by_mailbox: 2500 not found in vmstates [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:2458 inboxcount: Mailbox is set to 2500 [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8709 get_vm_state_by_imapuser: sdess not found in vmstates [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8719 get_vm_state_by_mailbox: Mailbox set to 2500 [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8741 get_vm_state_by_mailbox: 2500 not found in vmstates [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8709 get_vm_state_by_imapuser: sdess not found in vmstates [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8719 get_vm_state_by_mailbox: Mailbox set to 2500 [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8741 get_vm_state_by_mailbox: 2500 not found in vmstates [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:2529 inboxcount: Adding new vmstate for sdess [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:2538 inboxcount: Copied sdess to sdess [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8784 vmstate_insert: Inserting vm_state for user:sdess, mailbox 2500 [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:4656 init_mailstream: vm_state user is:sdess [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:4659 init_mailstream: mailstream not set. [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8529 mm_log: IMAP Info: Trying IP address [127.0.0.1] [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8529 mm_log: IMAP Info: Dovecot ready. [May 25 14:59:34] WARNING[3052]: app_voicemail.c:8533 mm_log: IMAP Warning: SECURITY PROBLEM: insecure server advertised AUTH=PLAIN [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8553 mm_login: Entering callback mm_login [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8438 mm_exists: Entering EXISTS callback for message 3 [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8709 get_vm_state_by_imapuser: asterisk not found in vmstates [May 25 14:59:34] WARNING[3052]: app_voicemail.c:8849 set_update: User asterisk mailbox not found for update. [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8529 mm_log: IMAP Info: [UNSEEN 1] First unseen. [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8478 mm_list: Delimiter set to / and mailbox {localhost}jdoe [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8480 mm_list: no inferiors [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8486 mm_list: unmarked [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8478 mm_list: Delimiter set to / and mailbox {localhost}var [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8482 mm_list: no select [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8478 mm_list: Delimiter set to / and mailbox {localhost}var/vmail [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8482 mm_list: no select [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8478 mm_list: Delimiter set to / and mailbox {localhost}Courrier ind&AOk-sirable [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8480 mm_list: no inferiors [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8486 mm_list: unmarked [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8478 mm_list: Delimiter set to / and mailbox {localhost}sdess [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8480 mm_list: no inferiors [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8486 mm_list: unmarked [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8478 mm_list: Delimiter set to / and mailbox {localhost}johndoe [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8480 mm_list: no inferiors [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8486 mm_list: unmarked [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8478 mm_list: Delimiter set to / and mailbox {localhost}INBOX [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8480 mm_list: no inferiors [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8486 mm_list: unmarked [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:4685 init_mailstream: Before mail_open, server: {localhost:143/imap/authuser=asterisk/notls/user=sdess}INBOX, box:0 [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8529 mm_log: IMAP Info: Reusing connection to localhost/user="sdess" [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8438 mm_exists: Entering EXISTS callback for message 3 [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8709 get_vm_state_by_imapuser: asterisk not found in vmstates [May 25 14:59:34] WARNING[3052]: app_voicemail.c:8849 set_update: User asterisk mailbox not found for update. [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8529 mm_log: IMAP Info: [UNSEEN 1] First unseen. [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8236 mm_searched: saving mailbox message number 1 as message 0. Interactive set to 0 [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8236 mm_searched: saving mailbox message number 2 as message 1. Interactive set to 0 [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8236 mm_searched: saving mailbox message number 3 as message 2. Interactive set to 0 [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8458 mm_flags: Entering FLAGS callback for message 1 [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8845 set_update: User sdess mailbox set for update. [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8458 mm_flags: Entering FLAGS callback for message 2 [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8845 set_update: User sdess mailbox set for update. [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8458 mm_flags: Entering FLAGS callback for message 3 [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8845 set_update: User sdess mailbox set for update. [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8719 get_vm_state_by_mailbox: Mailbox set to 2500 [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8724 get_vm_state_by_mailbox: comparing mailbox 2500 (i=0) to vmstate mailbox 2500 (i=0) [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:8727 get_vm_state_by_mailbox: Found it! [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:3017 leave_voicemail: Messagecount set to 3 [May 25 14:59:34] DEBUG[3052]: app_voicemail.c:3032 leave_voicemail: Messagecount set to 3 [May 25 14:59:34] DEBUG[3052]: rtp.c:2571 ast_rtp_raw_write: Difference is 688, ms is 106 [May 25 14:59:34] DEBUG[3052]: channel.c:2030 ast_settimeout: Scheduling timer at 160 sample intervals [May 25 14:59:34] -- Playing 'beep' (language 'fr') [May 25 14:59:35] DEBUG[3052]: channel.c:2030 ast_settimeout: Scheduling timer at 45 sample intervals [May 25 14:59:35] DEBUG[3052]: channel.c:2030 ast_settimeout: Scheduling timer at 0 sample intervals [May 25 14:59:35] DEBUG[3052]: channel.c:2030 ast_settimeout: Scheduling timer at 0 sample intervals [May 25 14:59:35] -- Recording the message [May 25 14:59:35] DEBUG[3052]: app.c:516 __ast_play_and_record: play_and_record: , /var/spool/asterisk/voicemail/default/2500/tmp/e2h3UP, 'gsm|wav49' [May 25 14:59:35] DEBUG[3052]: app.c:538 __ast_play_and_record: Recording Formats: sfmts=gsm [May 25 14:59:35] -- x=0, open writing: /var/spool/asterisk/voicemail/default/2500/tmp/e2h3UP format: gsm, 0xb7b1f6f8 [May 25 14:59:35] -- x=1, open writing: /var/spool/asterisk/voicemail/default/2500/tmp/e2h3UP format: wav49, 0xb7b2bfb0 [May 25 14:59:35] DEBUG[3052]: channel.c:2911 set_format: Set channel SIP/2400-08205710 to read format slin [May 25 14:59:37] DEBUG[3052]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [May 25 14:59:37] DEBUG[3052]: rtp.c:626 send_dtmf: Sending dtmf: 35 (#), at 192.168.2.27 [May 25 14:59:37] DEBUG[3052]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [May 25 14:59:37] DEBUG[3052]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [May 25 14:59:37] DEBUG[3052]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [May 25 14:59:37] DEBUG[3052]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [May 25 14:59:37] DEBUG[3052]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [May 25 14:59:37] DEBUG[3052]: rtp.c:626 send_dtmf: Sending dtmf: 35 (#), at 192.168.2.27 [May 25 14:59:37] -- User ended message by pressing # [May 25 14:59:37] DEBUG[3052]: channel.c:2911 set_format: Set channel SIP/2400-08205710 to read format ulaw [May 25 14:59:37] DEBUG[3052]: rtp.c:2571 ast_rtp_raw_write: Difference is 17760, ms is 2240 [May 25 14:59:37] DEBUG[3052]: channel.c:2030 ast_settimeout: Scheduling timer at 160 sample intervals [May 25 14:59:37] -- Playing 'auth-thankyou' (language 'fr') [May 25 14:59:37] DEBUG[3052]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [May 25 14:59:37] DEBUG[3052]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [May 25 14:59:38] DEBUG[3052]: channel.c:2030 ast_settimeout: Scheduling timer at 78 sample intervals [May 25 14:59:38] DEBUG[3052]: channel.c:2030 ast_settimeout: Scheduling timer at 0 sample intervals [May 25 14:59:38] DEBUG[3052]: channel.c:2030 ast_settimeout: Scheduling timer at 0 sample intervals [May 25 14:59:38] DEBUG[3052]: app.c:983 ast_lock_path: Locked path '/var/spool/asterisk/voicemail/default/2500/INBOX' [May 25 14:59:38] DEBUG[3052]: app.c:1004 ast_unlock_path: Unlocked path '/var/spool/asterisk/voicemail/default/2500/INBOX' [May 25 14:59:38] DEBUG[3052]: app_voicemail.c:2408 imap_store_file: Storing file '/var/spool/asterisk/voicemail/default/2500/INBOX/msg0003', format 'gsm' [May 25 14:59:38] DEBUG[3052]: app_voicemail.c:1973 make_email_file: newtmp: /var/spool/asterisk/voicemail/default/2500/tmp/fpczGS [May 25 14:59:38] DEBUG[3052]: app_voicemail.c:4656 init_mailstream: vm_state user is:sdess [May 25 14:59:38] DEBUG[3052]: app_voicemail.c:4685 init_mailstream: Before mail_open, server: {localhost:143/imap/authuser=asterisk/notls/user=sdess}INBOX, box:0 [May 25 14:59:38] DEBUG[3052]: app_voicemail.c:8529 mm_log: IMAP Info: Reusing connection to localhost/user="sdess" [May 25 14:59:38] DEBUG[3052]: app_voicemail.c:8438 mm_exists: Entering EXISTS callback for message 3 [May 25 14:59:38] DEBUG[3052]: app_voicemail.c:8709 get_vm_state_by_imapuser: asterisk not found in vmstates [May 25 14:59:38] WARNING[3052]: app_voicemail.c:8849 set_update: User asterisk mailbox not found for update. [May 25 14:59:38] DEBUG[3052]: app_voicemail.c:8529 mm_log: IMAP Info: [UNSEEN 1] First unseen. [May 25 14:59:38] DEBUG[3052]: app_voicemail.c:8438 mm_exists: Entering EXISTS callback for message 4 [May 25 14:59:38] DEBUG[3052]: app_voicemail.c:8845 set_update: User sdess mailbox set for update. [May 25 14:59:38] DEBUG[3052]: app_voicemail.c:2434 imap_store_file: /var/spool/asterisk/voicemail/default/2500/INBOX/msg0003 stored [May 25 14:59:38] DEBUG[3052]: app_voicemail.c:2018 sendmail: Attaching file '/var/spool/asterisk/voicemail/default/2500/INBOX/msg0003', format 'gsm', uservm is '2048', global is 2048 [May 25 14:59:38] DEBUG[3052]: app_voicemail.c:1973 make_email_file: newtmp: /var/spool/asterisk/voicemail/default/2500/tmp/Sghr6V [May 25 14:59:38] DEBUG[3052]: app_voicemail.c:2030 sendmail: Sent mail to sdess with command '/usr/sbin/sendmail -t' [May 25 14:59:38] DEBUG[3052]: app_voicemail.c:2458 inboxcount: Mailbox is set to 2500@default [May 25 14:59:38] DEBUG[3052]: app_voicemail.c:8709 get_vm_state_by_imapuser: sdess not found in vmstates [May 25 14:59:38] DEBUG[3052]: app_voicemail.c:8719 get_vm_state_by_mailbox: Mailbox set to 2500 [May 25 14:59:38] DEBUG[3052]: app_voicemail.c:8724 get_vm_state_by_mailbox: comparing mailbox 2500 (i=1) to vmstate mailbox 2500 (i=0) [May 25 14:59:38] DEBUG[3052]: app_voicemail.c:8741 get_vm_state_by_mailbox: 2500 not found in vmstates [May 25 14:59:38] DEBUG[3052]: app_voicemail.c:4656 init_mailstream: vm_state user is:sdess [May 25 14:59:38] DEBUG[3052]: app_voicemail.c:4685 init_mailstream: Before mail_open, server: {localhost:143/imap/authuser=asterisk/notls/user=sdess}INBOX, box:0 [May 25 14:59:38] DEBUG[3052]: app_voicemail.c:8529 mm_log: IMAP Info: Reusing connection to localhost/user="sdess" [May 25 14:59:38] DEBUG[3052]: app_voicemail.c:8438 mm_exists: Entering EXISTS callback for message 4 [May 25 14:59:38] DEBUG[3052]: app_voicemail.c:8709 get_vm_state_by_imapuser: asterisk not found in vmstates [May 25 14:59:38] WARNING[3052]: app_voicemail.c:8849 set_update: User asterisk mailbox not found for update. [May 25 14:59:38] DEBUG[3052]: app_voicemail.c:8529 mm_log: IMAP Info: [UNSEEN 1] First unseen. [May 25 14:59:38] DEBUG[3052]: app_voicemail.c:2458 inboxcount: Mailbox is set to 2500@default [May 25 14:59:38] DEBUG[3052]: app_voicemail.c:8709 get_vm_state_by_imapuser: sdess not found in vmstates [May 25 14:59:38] DEBUG[3052]: app_voicemail.c:8719 get_vm_state_by_mailbox: Mailbox set to 2500 [May 25 14:59:38] DEBUG[3052]: app_voicemail.c:8724 get_vm_state_by_mailbox: comparing mailbox 2500 (i=1) to vmstate mailbox 2500 (i=0) [May 25 14:59:38] DEBUG[3052]: app_voicemail.c:8741 get_vm_state_by_mailbox: 2500 not found in vmstates [May 25 14:59:38] DEBUG[3052]: app_voicemail.c:4656 init_mailstream: vm_state user is:sdess [May 25 14:59:38] DEBUG[3052]: app_voicemail.c:4685 init_mailstream: Before mail_open, server: {localhost:143/imap/authuser=asterisk/notls/user=sdess}INBOX, box:0 [May 25 14:59:38] DEBUG[3052]: app_voicemail.c:8529 mm_log: IMAP Info: Reusing connection to localhost/user="sdess" [May 25 14:59:38] DEBUG[3052]: app_voicemail.c:8438 mm_exists: Entering EXISTS callback for message 4 [May 25 14:59:38] DEBUG[3052]: app_voicemail.c:8709 get_vm_state_by_imapuser: asterisk not found in vmstates [May 25 14:59:38] WARNING[3052]: app_voicemail.c:8849 set_update: User asterisk mailbox not found for update. [May 25 14:59:38] DEBUG[3052]: app_voicemail.c:8529 mm_log: IMAP Info: [UNSEEN 1] First unseen. [May 25 14:59:38] DEBUG[3052]: app_voicemail.c:8236 mm_searched: saving mailbox message number 1 as message 0. Interactive set to 0 [May 25 14:59:38] DEBUG[3052]: app_voicemail.c:8236 mm_searched: saving mailbox message number 2 as message 1. Interactive set to 0 [May 25 14:59:38] DEBUG[3052]: app_voicemail.c:8236 mm_searched: saving mailbox message number 3 as message 2. Interactive set to 0 [May 25 14:59:38] DEBUG[3052]: app_voicemail.c:8236 mm_searched: saving mailbox message number 4 as message 3. Interactive set to 0 [May 25 14:59:38] DEBUG[3052]: app_voicemail.c:8458 mm_flags: Entering FLAGS callback for message 1 [May 25 14:59:38] DEBUG[3052]: app_voicemail.c:8845 set_update: User sdess mailbox set for update. [May 25 14:59:38] DEBUG[3052]: app_voicemail.c:8458 mm_flags: Entering FLAGS callback for message 2 [May 25 14:59:38] DEBUG[3052]: app_voicemail.c:8845 set_update: User sdess mailbox set for update. [May 25 14:59:38] DEBUG[3052]: app_voicemail.c:8458 mm_flags: Entering FLAGS callback for message 3 [May 25 14:59:38] DEBUG[3052]: app_voicemail.c:8845 set_update: User sdess mailbox set for update. [May 25 14:59:38] DEBUG[3052]: app_voicemail.c:8458 mm_flags: Entering FLAGS callback for message 4 [May 25 14:59:38] DEBUG[3052]: app_voicemail.c:8845 set_update: User sdess mailbox set for update. [May 25 14:59:38] DEBUG[3052]: app_macro.c:320 _macro_exec: Executed application: Voicemail [May 25 14:59:38] DEBUG[3052]: pbx.c:1809 pbx_extension_helper: Launching 'Goto' [May 25 14:59:38] -- Executing [s-BUSY@macro-stdexten:2] Goto("SIP/2400-08205710", "default|s|1") in new stack [May 25 14:59:38] -- Goto (default,s,1) [May 25 14:59:38] DEBUG[3052]: app_macro.c:320 _macro_exec: Executed application: Goto [May 25 14:59:38] == Channel 'SIP/2400-08205710' jumping out of macro 'stdexten' [May 25 14:59:38] WARNING[3052]: pbx.c:2450 __ast_pbx_run: Channel 'SIP/2400-08205710' sent into invalid extension 's' in context 'default', but no invalid handler [May 25 14:59:38] DEBUG[3052]: channel.c:1726 ast_hangup: Hanging up channel 'SIP/2400-08205710' [May 25 14:59:38] DEBUG[3052]: chan_sip.c:3313 sip_hangup: Hangup call SIP/2400-08205710, SIP callid a915f1b8-26735276-77f1ecab@192.168.2.27) [May 25 14:59:38] DEBUG[3052]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/2400-08205710 [May 25 14:59:38] DEBUG[3034]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 2400 [May 25 14:59:38] DEBUG[3034]: chan_sip.c:15321 sip_devicestate: Checking device state for peer 2400 [May 25 14:59:38] DEBUG[3034]: chan_sip.c:7646 reg_source_db: SIP Seeding peer from astdb: '2400' at 2400@192.168.2.27:5060 for 3600 [May 25 14:59:38] DEBUG[3034]: chan_sip.c:2360 sip_destroy_peer: Destroying SIP peer 2400 [May 25 14:59:38] DEBUG[3034]: devicestate.c:287 do_state_change: Changing state for SIP/2400 - state 1 (Not in use) [May 25 14:59:38] DEBUG[3050]: chan_sip.c:4365 find_call: = Found Their Call ID: a915f1b8-26735276-77f1ecab@192.168.2.27 Their Tag ADE7B794-187943D9 Our tag: as4788c128 [May 25 14:59:38] DEBUG[3050]: chan_sip.c:2090 __sip_ack: Stopping retransmission on 'a915f1b8-26735276-77f1ecab@192.168.2.27' of Request 102: Match Not Found [May 25 14:59:38] Really destroying SIP dialog 'a915f1b8-26735276-77f1ecab@192.168.2.27' Method: ACK [May 25 14:59:42] DEBUG[3050]: chan_sip.c:14893 sipsock_read: Invalid SIP message - rejected , no callid, len 594 [May 25 14:59:45] DEBUG[3050]: chan_sip.c:2576 do_setnat: Setting NAT on RTP to Off [May 25 14:59:45] DEBUG[3050]: chan_sip.c:4312 sip_alloc: Allocating new SIP dialog for 1067c228-31654de6-b5af249b@192.168.2.27 - INVITE (With RTP) [May 25 14:59:45] DEBUG[3050]: chan_sip.c:14709 handle_request: **** Received INVITE (5) - Command in SIP INVITE [May 25 14:59:45] DEBUG[3050]: chan_sip.c:2576 do_setnat: Setting NAT on RTP to Off [May 25 14:59:45] DEBUG[3050]: chan_sip.c:2501 sip_destroy_user: Destroying user object from memory: 2400 [May 25 14:59:45] DEBUG[3050]: chan_sip.c:4365 find_call: = Found Their Call ID: 1067c228-31654de6-b5af249b@192.168.2.27 Their Tag CF15CE04-CB9D3EC9 Our tag: as4bda968f [May 25 14:59:45] DEBUG[3050]: chan_sip.c:14709 handle_request: **** Received ACK (6) - Command in SIP ACK [May 25 14:59:45] DEBUG[3050]: chan_sip.c:2090 __sip_ack: Stopping retransmission on '1067c228-31654de6-b5af249b@192.168.2.27' of Response 1: Match Not Found [May 25 14:59:45] DEBUG[3050]: chan_sip.c:4365 find_call: = Found Their Call ID: 1067c228-31654de6-b5af249b@192.168.2.27 Their Tag CF15CE04-CB9D3EC9 Our tag: as4bda968f [May 25 14:59:45] DEBUG[3050]: chan_sip.c:14709 handle_request: **** Received INVITE (5) - Command in SIP INVITE [May 25 14:59:45] DEBUG[3050]: chan_sip.c:2576 do_setnat: Setting NAT on RTP to Off [May 25 14:59:45] DEBUG[3050]: chan_sip.c:2501 sip_destroy_user: Destroying user object from memory: 2400 [May 25 14:59:45] DEBUG[3050]: chan_sip.c:5136 process_sdp: T38 state changed to 0 on channel [May 25 14:59:45] DEBUG[3050]: chan_sip.c:5216 process_sdp: We're settling with these formats: 0xc (ulaw|alaw) [May 25 14:59:45] DEBUG[3050]: chan_sip.c:13418 handle_request_invite: Checking SIP call limits for device 2400 [May 25 14:59:45] DEBUG[3050]: chan_sip.c:3004 update_call_counter: Updating call counter for incoming call [May 25 14:59:45] DEBUG[3050]: chan_sip.c:3806 sip_new: *** Our native formats are 0x4 (ulaw) [May 25 14:59:45] DEBUG[3050]: chan_sip.c:3807 sip_new: *** Joint capabilities are 0xc (ulaw|alaw) [May 25 14:59:45] DEBUG[3050]: chan_sip.c:3808 sip_new: *** Our capabilities are 0xe (gsm|ulaw|alaw) [May 25 14:59:45] DEBUG[3050]: chan_sip.c:3809 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [May 25 14:59:45] DEBUG[3050]: chan_sip.c:3832 sip_new: This channel will not be able to handle video. [May 25 14:59:45] DEBUG[3050]: chan_sip.c:7994 build_route: build_route: Contact hop: [May 25 14:59:45] DEBUG[3050]: chan_sip.c:13492 handle_request_invite: SIP/2400-08206c90: New call is still down.... Trying... [May 25 14:59:45] DEBUG[3050]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/2400-08206c90 [May 25 14:59:45] DEBUG[3034]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 2400 [May 25 14:59:45] DEBUG[3059]: pbx.c:1809 pbx_extension_helper: Launching 'VoiceMailMain' [May 25 14:59:45] DEBUG[3034]: chan_sip.c:15321 sip_devicestate: Checking device state for peer 2400 [May 25 14:59:45] -- Executing [7777@sip-internal:1] VoiceMailMain("SIP/2400-08206c90", "2500@default") in new stack [May 25 14:59:45] DEBUG[3059]: app_voicemail.c:6268 vm_execmain: Before ast_answer [May 25 14:59:45] DEBUG[3059]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/2400-08206c90 [May 25 14:59:45] DEBUG[3059]: chan_sip.c:3464 sip_answer: SIP answering channel: SIP/2400-08206c90 [May 25 14:59:45] DEBUG[3059]: chan_sip.c:6432 transmit_response_with_sdp: Setting framing from config on incoming call [May 25 14:59:45] DEBUG[3059]: chan_sip.c:6198 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: True [May 25 14:59:45] DEBUG[3059]: chan_sip.c:6199 add_sdp: ** Our prefcodec: 0x0 (nothing) [May 25 14:59:45] DEBUG[3059]: chan_sip.c:6330 add_sdp: -- Done with adding codecs to SDP [May 25 14:59:45] DEBUG[3059]: channel.c:2447 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23) [May 25 14:59:45] DEBUG[3059]: chan_sip.c:6375 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) [May 25 14:59:45] DEBUG[3059]: app_voicemail.c:6175 vm_authenticate: Before find user for mailbox 2500 [May 25 14:59:45] DEBUG[3034]: chan_sip.c:7646 reg_source_db: SIP Seeding peer from astdb: '2400' at 2400@192.168.2.27:5060 for 3600 [May 25 14:59:45] DEBUG[3034]: chan_sip.c:2360 sip_destroy_peer: Destroying SIP peer 2400 [May 25 14:59:45] DEBUG[3034]: devicestate.c:287 do_state_change: Changing state for SIP/2400 - state 1 (Not in use) [May 25 14:59:45] DEBUG[3034]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 2400 [May 25 14:59:45] DEBUG[3034]: chan_sip.c:15321 sip_devicestate: Checking device state for peer 2400 [May 25 14:59:45] DEBUG[3034]: chan_sip.c:7646 reg_source_db: SIP Seeding peer from astdb: '2400' at 2400@192.168.2.27:5060 for 3600 [May 25 14:59:45] DEBUG[3034]: chan_sip.c:2360 sip_destroy_peer: Destroying SIP peer 2400 [May 25 14:59:45] DEBUG[3034]: devicestate.c:287 do_state_change: Changing state for SIP/2400 - state 1 (Not in use) [May 25 14:59:45] DEBUG[3059]: rtp.c:2701 ast_rtp_write: Ooh, format changed from unknown to ulaw [May 25 14:59:45] DEBUG[3059]: rtp.c:2718 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [May 25 14:59:45] DEBUG[3059]: channel.c:2030 ast_settimeout: Scheduling timer at 160 sample intervals [May 25 14:59:45] -- Playing 'vm-password' (language 'fr') [May 25 14:59:45] DEBUG[3050]: chan_sip.c:4365 find_call: = Found Their Call ID: 1067c228-31654de6-b5af249b@192.168.2.27 Their Tag CF15CE04-CB9D3EC9 Our tag: as36bf9645 [May 25 14:59:45] DEBUG[3050]: chan_sip.c:14709 handle_request: **** Received ACK (6) - Command in SIP ACK [May 25 14:59:45] DEBUG[3050]: chan_sip.c:2090 __sip_ack: Stopping retransmission on '1067c228-31654de6-b5af249b@192.168.2.27' of Response 2: Match Not Found [May 25 14:59:46] DEBUG[3059]: channel.c:2030 ast_settimeout: Scheduling timer at 106 sample intervals [May 25 14:59:46] DEBUG[3059]: channel.c:2030 ast_settimeout: Scheduling timer at 0 sample intervals [May 25 14:59:46] DEBUG[3059]: channel.c:2030 ast_settimeout: Scheduling timer at 0 sample intervals [May 25 14:59:47] DEBUG[3050]: chan_sip.c:4365 find_call: = Found Their Call ID: 1067c228-31654de6-b5af249b@192.168.2.27 Their Tag CF15CE04-CB9D3EC9 Our tag: as36bf9645 [May 25 14:59:47] DEBUG[3050]: chan_sip.c:14709 handle_request: **** Received BYE (8) - Command in SIP BYE [May 25 14:59:47] DEBUG[3050]: chan_sip.c:1634 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 1067c228-31654de6-b5af249b@192.168.2.27 [May 25 14:59:47] DEBUG[3050]: chan_sip.c:14263 handle_request_bye: Received bye, issuing owner hangup [May 25 14:59:47] WARNING[3059]: app_voicemail.c:6186 vm_authenticate: Unable to read password [May 25 14:59:47] DEBUG[3059]: app_voicemail.c:6351 vm_execmain: After vm_authenticate [May 25 14:59:47] DEBUG[3059]: app_voicemail.c:8719 get_vm_state_by_mailbox: Mailbox set to 2500 [May 25 14:59:47] DEBUG[3059]: app_voicemail.c:8724 get_vm_state_by_mailbox: comparing mailbox 2500 (i=0) to vmstate mailbox 2500 (i=0) [May 25 14:59:47] DEBUG[3059]: app_voicemail.c:8727 get_vm_state_by_mailbox: Found it! [May 25 14:59:47] DEBUG[3059]: app_voicemail.c:8757 vmstate_insert: Duplicate mailbox 2500, copying message info... [May 25 14:59:47] DEBUG[3059]: app_voicemail.c:8761 vmstate_insert: check_msgArray before memcpy [May 25 14:59:47] DEBUG[3059]: app_voicemail.c:8766 vmstate_insert: check_msgArray after memcpy [May 25 14:59:47] DEBUG[3059]: app_voicemail.c:8868 check_msgArray: Item 0 set to 1 [May 25 14:59:47] DEBUG[3059]: app_voicemail.c:8868 check_msgArray: Item 1 set to 2 [May 25 14:59:47] DEBUG[3059]: app_voicemail.c:8868 check_msgArray: Item 2 set to 3 [May 25 14:59:47] DEBUG[3059]: app_voicemail.c:8868 check_msgArray: Item 3 set to 4 [May 25 14:59:47] DEBUG[3059]: app_voicemail.c:8784 vmstate_insert: Inserting vm_state for user:, mailbox 2500