[May 24 15:23:25] Asterisk 1.4.4, Copyright (C) 1999 - 2006 Digium, Inc. and others.
[May 24 15:23:25] Created by Mark Spencer <markster@digium.com>
[May 24 15:23:25] Asterisk comes with ABSOLUTELY NO WARRANTY; type 'core show warranty' for details.
[May 24 15:23:25] This is free software, with components licensed under the GNU General Public
[May 24 15:23:25] License version 2 and other licenses; you are welcome to redistribute it under
[May 24 15:23:25] certain conditions. Type 'core show license' for details.
[May 24 15:23:25] =========================================================================
[May 24 15:23:39] DEBUG[3577]: chan_sip.c:7994 build_route: build_route: Contact hop: <sip:2400@192.168.2.36>
[May 24 15:23:39] DEBUG[3577]: chan_sip.c:13492 handle_request_invite: SIP/2400-08221068: New call is still down.... Trying... 
[May 24 15:23:39] DEBUG[3577]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/2400-08221068
[May 24 15:23:39] DEBUG[3561]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 2400
[May 24 15:23:39] DEBUG[3561]: chan_sip.c:15321 sip_devicestate: Checking device state for peer 2400
[May 24 15:23:39] DEBUG[3579]: pbx.c:1809 pbx_extension_helper: Launching 'VoiceMailMain'
[May 24 15:23:39]     -- Executing [7777@sip-internal:1] VoiceMailMain("SIP/2400-08221068", "2500@default") in new stack
[May 24 15:23:39] DEBUG[3579]: app_voicemail.c:6254 vm_execmain: Before ast_answer
[May 24 15:23:39] DEBUG[3579]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/2400-08221068
[May 24 15:23:39] DEBUG[3579]: chan_sip.c:3464 sip_answer: SIP answering channel: SIP/2400-08221068
[May 24 15:23:39] DEBUG[3579]: chan_sip.c:6432 transmit_response_with_sdp: Setting framing from config on incoming call
[May 24 15:23:39] DEBUG[3579]: chan_sip.c:6198 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: True
[May 24 15:23:39] DEBUG[3579]: chan_sip.c:6199 add_sdp: ** Our prefcodec: 0x0 (nothing) 
[May 24 15:23:39] DEBUG[3579]: chan_sip.c:6330 add_sdp: -- Done with adding codecs to SDP
[May 24 15:23:39] DEBUG[3579]: channel.c:2447 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=23)
[May 24 15:23:39] DEBUG[3579]: chan_sip.c:6375 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw)
[May 24 15:23:39] DEBUG[3561]: chan_sip.c:7646 reg_source_db: SIP Seeding peer from astdb: '2400' at 2400@192.168.2.36:5060 for 3600
[May 24 15:23:39] DEBUG[3561]: chan_sip.c:2360 sip_destroy_peer: Destroying SIP peer 2400
[May 24 15:23:39] DEBUG[3561]: devicestate.c:287 do_state_change: Changing state for SIP/2400 - state 1 (Not in use)
[May 24 15:23:39] DEBUG[3561]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 2400
[May 24 15:23:39] DEBUG[3561]: chan_sip.c:15321 sip_devicestate: Checking device state for peer 2400
[May 24 15:23:39] DEBUG[3579]: app_voicemail.c:6161 vm_authenticate: Before find user for mailbox 2500
[May 24 15:23:39] DEBUG[3561]: chan_sip.c:7646 reg_source_db: SIP Seeding peer from astdb: '2400' at 2400@192.168.2.36:5060 for 3600
[May 24 15:23:39] DEBUG[3561]: chan_sip.c:2360 sip_destroy_peer: Destroying SIP peer 2400
[May 24 15:23:39] DEBUG[3561]: devicestate.c:287 do_state_change: Changing state for SIP/2400 - state 1 (Not in use)
[May 24 15:23:39] DEBUG[3579]: rtp.c:2701 ast_rtp_write: Ooh, format changed from unknown to ulaw
[May 24 15:23:39] DEBUG[3579]: rtp.c:2718 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160
[May 24 15:23:39] DEBUG[3579]: channel.c:2030 ast_settimeout: Scheduling timer at 160 sample intervals
[May 24 15:23:39]     -- <SIP/2400-08221068> Playing 'vm-password' (language 'fr')
[May 24 15:23:39] DEBUG[3577]: chan_sip.c:4365 find_call: = Found Their Call ID: 7bee061f-155e5149-d716a710@192.168.2.36 Their Tag 1BD1493-DEC16D0A Our tag: as31b43ac4
[May 24 15:23:39] DEBUG[3577]: chan_sip.c:14709 handle_request: **** Received ACK (6) - Command in SIP ACK
[May 24 15:23:39] DEBUG[3577]: chan_sip.c:2090 __sip_ack: Stopping retransmission on '7bee061f-155e5149-d716a710@192.168.2.36' of Response 2: Match Not Found
[May 24 15:23:39] DEBUG[3579]: rtp.c:875 ast_rtcp_read: Got RTCP report of 76 bytes
[May 24 15:23:40] DEBUG[3579]: channel.c:2030 ast_settimeout: Scheduling timer at 106 sample intervals
[May 24 15:23:40] DEBUG[3579]: channel.c:2030 ast_settimeout: Scheduling timer at 0 sample intervals
[May 24 15:23:40] DEBUG[3579]: channel.c:2030 ast_settimeout: Scheduling timer at 0 sample intervals
[May 24 15:23:43] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[May 24 15:23:43] DEBUG[3579]: rtp.c:626 send_dtmf: Sending dtmf: 52 (4), at 192.168.2.36
[May 24 15:23:43] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[May 24 15:23:43] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[May 24 15:23:43] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[May 24 15:23:43] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[May 24 15:23:43] DEBUG[3579]: rtp.c:626 send_dtmf: Sending dtmf: 52 (4), at 192.168.2.36
[May 24 15:23:43] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[May 24 15:23:43] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[May 24 15:23:43] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[May 24 15:23:43] DEBUG[3579]: rtp.c:626 send_dtmf: Sending dtmf: 51 (3), at 192.168.2.36
[May 24 15:23:43] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[May 24 15:23:43] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[May 24 15:23:43] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[May 24 15:23:43] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[May 24 15:23:43] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[May 24 15:23:43] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[May 24 15:23:43] DEBUG[3579]: rtp.c:626 send_dtmf: Sending dtmf: 51 (3), at 192.168.2.36
[May 24 15:23:43] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[May 24 15:23:43] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000003 (len = 4)
[May 24 15:23:43] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[May 24 15:23:43] DEBUG[3579]: rtp.c:626 send_dtmf: Sending dtmf: 50 (2), at 192.168.2.36
[May 24 15:23:43] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[May 24 15:23:43] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[May 24 15:23:43] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[May 24 15:23:43] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[May 24 15:23:43] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[May 24 15:23:43] DEBUG[3579]: rtp.c:626 send_dtmf: Sending dtmf: 50 (2), at 192.168.2.36
[May 24 15:23:43] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[May 24 15:23:43] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[May 24 15:23:43] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[May 24 15:23:43] DEBUG[3579]: rtp.c:626 send_dtmf: Sending dtmf: 49 (1), at 192.168.2.36
[May 24 15:23:43] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[May 24 15:23:43] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[May 24 15:23:43] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[May 24 15:23:43] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[May 24 15:23:43] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[May 24 15:23:43] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[May 24 15:23:43] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[May 24 15:23:43] DEBUG[3579]: rtp.c:626 send_dtmf: Sending dtmf: 49 (1), at 192.168.2.36
[May 24 15:23:43] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[May 24 15:23:43] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[May 24 15:23:45] DEBUG[3579]: app_voicemail.c:6337 vm_execmain: After vm_authenticate
[May 24 15:23:45] DEBUG[3579]: app_voicemail.c:8701 get_vm_state_by_mailbox: Mailbox set to 2500
[May 24 15:23:45] DEBUG[3579]: app_voicemail.c:8723 get_vm_state_by_mailbox: 2500 not found in vmstates
[May 24 15:23:45] DEBUG[3579]: app_voicemail.c:8766 vmstate_insert: Inserting vm_state for user:, mailbox 2500
[May 24 15:23:45] DEBUG[3579]: app_voicemail.c:6373 vm_execmain: Before open_mailbox
[May 24 15:23:45] DEBUG[3579]: app_voicemail.c:4721 open_mailbox: Before init_mailstream, user is sdess
[May 24 15:23:45] DEBUG[3579]: app_voicemail.c:4674 init_mailstream: vm_state user is:sdess
[May 24 15:23:45] DEBUG[3579]: app_voicemail.c:4677 init_mailstream: mailstream not set.
[May 24 15:23:45] DEBUG[3579]: app_voicemail.c:8511 mm_log: IMAP Info: Trying IP address [127.0.0.1]
[May 24 15:23:45] DEBUG[3579]: app_voicemail.c:8511 mm_log: IMAP Info: Dovecot ready.
[May 24 15:23:45] WARNING[3579]: app_voicemail.c:8515 mm_log: IMAP Warning: SECURITY PROBLEM: insecure server advertised AUTH=PLAIN
[May 24 15:23:45] DEBUG[3579]: app_voicemail.c:8535 mm_login: Entering callback mm_login
[May 24 15:23:45] DEBUG[3579]: app_voicemail.c:8420 mm_exists: Entering EXISTS callback for message 0
[May 24 15:23:45] DEBUG[3579]: app_voicemail.c:8511 mm_log: IMAP Info: Mailbox is empty
[May 24 15:23:45] DEBUG[3579]: app_voicemail.c:8460 mm_list: Delimiter set to / and mailbox {localhost}jdoe
[May 24 15:23:45] DEBUG[3579]: app_voicemail.c:8462 mm_list: no inferiors
[May 24 15:23:45] DEBUG[3579]: app_voicemail.c:8468 mm_list: unmarked
[May 24 15:23:45] DEBUG[3579]: app_voicemail.c:8460 mm_list: Delimiter set to / and mailbox {localhost}var
[May 24 15:23:45] DEBUG[3579]: app_voicemail.c:8464 mm_list: no select
[May 24 15:23:45] DEBUG[3579]: app_voicemail.c:8460 mm_list: Delimiter set to / and mailbox {localhost}var/vmail
[May 24 15:23:45] DEBUG[3579]: app_voicemail.c:8464 mm_list: no select
[May 24 15:23:45] DEBUG[3579]: app_voicemail.c:8460 mm_list: Delimiter set to / and mailbox {localhost}Courrier ind&AOk-sirable
[May 24 15:23:45] DEBUG[3579]: app_voicemail.c:8462 mm_list: no inferiors
[May 24 15:23:45] DEBUG[3579]: app_voicemail.c:8468 mm_list: unmarked
[May 24 15:23:45] DEBUG[3579]: app_voicemail.c:8460 mm_list: Delimiter set to / and mailbox {localhost}sdess
[May 24 15:23:45] DEBUG[3579]: app_voicemail.c:8462 mm_list: no inferiors
[May 24 15:23:45] DEBUG[3579]: app_voicemail.c:8468 mm_list: unmarked
[May 24 15:23:45] DEBUG[3579]: app_voicemail.c:8460 mm_list: Delimiter set to / and mailbox {localhost}johndoe
[May 24 15:23:45] DEBUG[3579]: app_voicemail.c:8462 mm_list: no inferiors
[May 24 15:23:45] DEBUG[3579]: app_voicemail.c:8468 mm_list: unmarked
[May 24 15:23:45] DEBUG[3579]: app_voicemail.c:8460 mm_list: Delimiter set to / and mailbox {localhost}INBOX
[May 24 15:23:45] DEBUG[3579]: app_voicemail.c:8462 mm_list: no inferiors
[May 24 15:23:45] DEBUG[3579]: app_voicemail.c:8468 mm_list: unmarked
[May 24 15:23:45] DEBUG[3579]: app_voicemail.c:4703 init_mailstream: Before mail_open, server: {localhost:143/imap/authuser=asterisk/notls/user=sdess}INBOX, box:1
[May 24 15:23:45] DEBUG[3579]: app_voicemail.c:8511 mm_log: IMAP Info: Reusing connection to localhost/user="sdess"
[May 24 15:23:45] DEBUG[3579]: app_voicemail.c:8420 mm_exists: Entering EXISTS callback for message 0
[May 24 15:23:45] DEBUG[3579]: app_voicemail.c:8511 mm_log: IMAP Info: Mailbox is empty
[May 24 15:23:45] ERROR[3579]: app_voicemail.c:8518 mm_log: IMAP Error: Quota not available on this IMAP server
[May 24 15:23:45] DEBUG[3579]: app_voicemail.c:4752 open_mailbox: Before mail_search_full, user is sdess
[May 24 15:23:45] DEBUG[3579]: app_voicemail.c:6379 vm_execmain: Number of old messages: 0
[May 24 15:23:45] DEBUG[3579]: app_voicemail.c:4721 open_mailbox: Before init_mailstream, user is sdess
[May 24 15:23:45] DEBUG[3579]: app_voicemail.c:4674 init_mailstream: vm_state user is:sdess
[May 24 15:23:45] DEBUG[3579]: app_voicemail.c:4703 init_mailstream: Before mail_open, server: {localhost:143/imap/authuser=asterisk/notls/user=sdess}INBOX, box:0
[May 24 15:23:45] DEBUG[3579]: app_voicemail.c:8511 mm_log: IMAP Info: Reusing connection to localhost/user="sdess"
[May 24 15:23:45] DEBUG[3579]: app_voicemail.c:8420 mm_exists: Entering EXISTS callback for message 0
[May 24 15:23:45] DEBUG[3579]: app_voicemail.c:8511 mm_log: IMAP Info: Mailbox is empty
[May 24 15:23:45] ERROR[3579]: app_voicemail.c:8518 mm_log: IMAP Error: Quota not available on this IMAP server
[May 24 15:23:45] DEBUG[3579]: app_voicemail.c:4752 open_mailbox: Before mail_search_full, user is sdess
[May 24 15:23:45] DEBUG[3579]: app_voicemail.c:6386 vm_execmain: Number of new messages: 0
[May 24 15:23:45] DEBUG[3579]: app_voicemail.c:6431 vm_execmain: Checking quotas: comparing 0 to 0
[May 24 15:23:45] DEBUG[3579]: rtp.c:2571 ast_rtp_raw_write: Difference is 43880, ms is 5505
[May 24 15:23:45] DEBUG[3579]: channel.c:2030 ast_settimeout: Scheduling timer at 160 sample intervals
[May 24 15:23:45]     -- <SIP/2400-08221068> Playing 'vm-youhave' (language 'fr')
[May 24 15:23:46] DEBUG[3579]: channel.c:2030 ast_settimeout: Scheduling timer at 1 sample intervals
[May 24 15:23:46] DEBUG[3579]: channel.c:2030 ast_settimeout: Scheduling timer at 0 sample intervals
[May 24 15:23:46] DEBUG[3579]: channel.c:2030 ast_settimeout: Scheduling timer at 0 sample intervals
[May 24 15:23:46] DEBUG[3579]: channel.c:2030 ast_settimeout: Scheduling timer at 160 sample intervals
[May 24 15:23:46]     -- <SIP/2400-08221068> Playing 'vm-no' (language 'fr')
[May 24 15:23:47] DEBUG[3579]: channel.c:2030 ast_settimeout: Scheduling timer at 17 sample intervals
[May 24 15:23:47] DEBUG[3579]: channel.c:2030 ast_settimeout: Scheduling timer at 0 sample intervals
[May 24 15:23:47] DEBUG[3579]: channel.c:2030 ast_settimeout: Scheduling timer at 0 sample intervals
[May 24 15:23:47] DEBUG[3579]: channel.c:2030 ast_settimeout: Scheduling timer at 160 sample intervals
[May 24 15:23:47]     -- <SIP/2400-08221068> Playing 'vm-messages' (language 'fr')
[May 24 15:23:48] DEBUG[3579]: channel.c:2030 ast_settimeout: Scheduling timer at 136 sample intervals
[May 24 15:23:48] DEBUG[3579]: channel.c:2030 ast_settimeout: Scheduling timer at 0 sample intervals
[May 24 15:23:48] DEBUG[3579]: channel.c:2030 ast_settimeout: Scheduling timer at 0 sample intervals
[May 24 15:23:48] DEBUG[3579]: channel.c:2030 ast_settimeout: Scheduling timer at 160 sample intervals
[May 24 15:23:48]     -- <SIP/2400-08221068> Playing 'vm-opts' (language 'fr')
[May 24 15:23:49] DEBUG[3579]: rtp.c:875 ast_rtcp_read: Got RTCP report of 76 bytes
[May 24 15:23:49] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[May 24 15:23:49] DEBUG[3579]: rtp.c:626 send_dtmf: Sending dtmf: 48 (0), at 192.168.2.36
[May 24 15:23:50] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[May 24 15:23:50] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[May 24 15:23:50] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[May 24 15:23:50] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[May 24 15:23:50] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[May 24 15:23:50] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[May 24 15:23:50] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[May 24 15:23:50] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[May 24 15:23:50] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[May 24 15:23:50] DEBUG[3579]: rtp.c:626 send_dtmf: Sending dtmf: 48 (0), at 192.168.2.36
[May 24 15:23:50] DEBUG[3579]: channel.c:2030 ast_settimeout: Scheduling timer at 0 sample intervals
[May 24 15:23:50] DEBUG[3579]: channel.c:2030 ast_settimeout: Scheduling timer at 160 sample intervals
[May 24 15:23:50]     -- <SIP/2400-08221068> Playing 'vm-options' (language 'fr')
[May 24 15:23:50] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[May 24 15:23:50] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[May 24 15:23:54] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[May 24 15:23:54] DEBUG[3579]: rtp.c:626 send_dtmf: Sending dtmf: 52 (4), at 192.168.2.36
[May 24 15:23:54] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[May 24 15:23:54] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[May 24 15:23:54] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[May 24 15:23:54] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[May 24 15:23:54] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[May 24 15:23:54] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[May 24 15:23:54] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[May 24 15:23:54] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[May 24 15:23:54] DEBUG[3579]: rtp.c:626 send_dtmf: Sending dtmf: 52 (4), at 192.168.2.36
[May 24 15:23:54] DEBUG[3579]: channel.c:2030 ast_settimeout: Scheduling timer at 0 sample intervals
[May 24 15:23:54] DEBUG[3579]: channel.c:2030 ast_settimeout: Scheduling timer at 160 sample intervals
[May 24 15:23:54]     -- <SIP/2400-08221068> Playing 'vm-tempgreeting2' (language 'fr')
[May 24 15:23:54] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[May 24 15:23:54] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000004 (len = 4)
[May 24 15:23:58] DEBUG[3577]: chan_sip.c:2011 __sip_autodestruct: Auto destroying SIP dialog 'f1eed69f-b2aa6cb9-5a7ddca6@192.168.2.41'
[May 24 15:23:58] DEBUG[3577]: chan_sip.c:3110 sip_destroy: Destroying SIP dialog f1eed69f-b2aa6cb9-5a7ddca6@192.168.2.41
[May 24 15:23:58] Really destroying SIP dialog 'f1eed69f-b2aa6cb9-5a7ddca6@192.168.2.41' Method: REGISTER
[May 24 15:23:59] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[May 24 15:23:59] DEBUG[3579]: rtp.c:626 send_dtmf: Sending dtmf: 49 (1), at 192.168.2.36
[May 24 15:23:59] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[May 24 15:23:59] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[May 24 15:23:59] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[May 24 15:23:59] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[May 24 15:23:59] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[May 24 15:23:59] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[May 24 15:23:59] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[May 24 15:23:59] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[May 24 15:23:59] DEBUG[3579]: rtp.c:626 send_dtmf: Sending dtmf: 49 (1), at 192.168.2.36
[May 24 15:23:59] DEBUG[3579]: channel.c:2030 ast_settimeout: Scheduling timer at 0 sample intervals
[May 24 15:23:59]     -- Recording the message
[May 24 15:23:59] DEBUG[3579]: app.c:516 __ast_play_and_record: play_and_record: vm-rec-temp, /var/spool/asterisk/voicemail/default/2500/temp, 'gsm|wav49'
[May 24 15:23:59] DEBUG[3579]: channel.c:2030 ast_settimeout: Scheduling timer at 160 sample intervals
[May 24 15:23:59]     -- <SIP/2400-08221068> Playing 'vm-rec-temp' (language 'fr')
[May 24 15:23:59] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[May 24 15:23:59] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[May 24 15:23:59] DEBUG[3579]: rtp.c:875 ast_rtcp_read: Got RTCP report of 76 bytes
[May 24 15:24:00] DEBUG[3577]: chan_sip.c:2011 __sip_autodestruct: Auto destroying SIP dialog 'd81ecddc-c20c99ce-152d3d27@192.168.2.41'
[May 24 15:24:00] DEBUG[3577]: chan_sip.c:3110 sip_destroy: Destroying SIP dialog d81ecddc-c20c99ce-152d3d27@192.168.2.41
[May 24 15:24:00] Really destroying SIP dialog 'd81ecddc-c20c99ce-152d3d27@192.168.2.41' Method: REGISTER
[May 24 15:24:04] DEBUG[3579]: channel.c:2030 ast_settimeout: Scheduling timer at 145 sample intervals
[May 24 15:24:04] DEBUG[3579]: channel.c:2030 ast_settimeout: Scheduling timer at 0 sample intervals
[May 24 15:24:04] DEBUG[3579]: channel.c:2030 ast_settimeout: Scheduling timer at 0 sample intervals
[May 24 15:24:04] DEBUG[3579]: channel.c:2030 ast_settimeout: Scheduling timer at 160 sample intervals
[May 24 15:24:04]     -- <SIP/2400-08221068> Playing 'beep' (language 'fr')
[May 24 15:24:04] DEBUG[3579]: channel.c:2030 ast_settimeout: Scheduling timer at 45 sample intervals
[May 24 15:24:04] DEBUG[3579]: channel.c:2030 ast_settimeout: Scheduling timer at 0 sample intervals
[May 24 15:24:04] DEBUG[3579]: channel.c:2030 ast_settimeout: Scheduling timer at 0 sample intervals
[May 24 15:24:04] DEBUG[3579]: app.c:538 __ast_play_and_record: Recording Formats: sfmts=gsm
[May 24 15:24:04]     -- x=0, open writing:  /var/spool/asterisk/voicemail/default/2500/temp format: gsm, 0x821ea78
[May 24 15:24:04]     -- x=1, open writing:  /var/spool/asterisk/voicemail/default/2500/temp format: wav49, 0x821ed48
[May 24 15:24:04] DEBUG[3579]: channel.c:2911 set_format: Set channel SIP/2400-08221068 to read format slin
[May 24 15:24:07] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[May 24 15:24:07] DEBUG[3579]: rtp.c:626 send_dtmf: Sending dtmf: 35 (#), at 192.168.2.36
[May 24 15:24:07] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[May 24 15:24:07] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[May 24 15:24:07] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[May 24 15:24:07] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[May 24 15:24:07] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[May 24 15:24:07] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[May 24 15:24:07] DEBUG[3579]: rtp.c:626 send_dtmf: Sending dtmf: 35 (#), at 192.168.2.36
[May 24 15:24:07]     -- User ended message by pressing #
[May 24 15:24:07] DEBUG[3579]: channel.c:2911 set_format: Set channel SIP/2400-08221068 to read format ulaw
[May 24 15:24:07] DEBUG[3579]: rtp.c:2571 ast_rtp_raw_write: Difference is 25200, ms is 3170
[May 24 15:24:07] DEBUG[3579]: channel.c:2030 ast_settimeout: Scheduling timer at 160 sample intervals
[May 24 15:24:07]     -- <SIP/2400-08221068> Playing 'auth-thankyou' (language 'fr')
[May 24 15:24:07] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[May 24 15:24:07] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[May 24 15:24:08] DEBUG[3579]: channel.c:2030 ast_settimeout: Scheduling timer at 78 sample intervals
[May 24 15:24:08] DEBUG[3579]: channel.c:2030 ast_settimeout: Scheduling timer at 0 sample intervals
[May 24 15:24:08] DEBUG[3579]: channel.c:2030 ast_settimeout: Scheduling timer at 0 sample intervals
[May 24 15:24:08] DEBUG[3579]: channel.c:2030 ast_settimeout: Scheduling timer at 160 sample intervals
[May 24 15:24:08]     -- <SIP/2400-08221068> Playing 'vm-review' (language 'fr')
[May 24 15:24:09] DEBUG[3579]: rtp.c:875 ast_rtcp_read: Got RTCP report of 76 bytes
[May 24 15:24:15] DEBUG[3579]: channel.c:2030 ast_settimeout: Scheduling timer at 53 sample intervals
[May 24 15:24:15] DEBUG[3579]: channel.c:2030 ast_settimeout: Scheduling timer at 0 sample intervals
[May 24 15:24:15] DEBUG[3579]: channel.c:2030 ast_settimeout: Scheduling timer at 0 sample intervals
[May 24 15:24:15] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[May 24 15:24:15] DEBUG[3579]: rtp.c:626 send_dtmf: Sending dtmf: 49 (1), at 192.168.2.36
[May 24 15:24:15] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[May 24 15:24:15] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[May 24 15:24:15] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[May 24 15:24:15] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[May 24 15:24:15] DEBUG[3569]: chan_iax2.c:7726 iax2_do_register: Allocate call number
[May 24 15:24:15] DEBUG[3569]: chan_iax2.c:7732 iax2_do_register: Registration created on call 2
[May 24 15:24:15] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[May 24 15:24:15] DEBUG[3579]: rtp.c:626 send_dtmf: Sending dtmf: 49 (1), at 192.168.2.36
[May 24 15:24:15]     -- Saving message as is
[May 24 15:24:15] DEBUG[3579]: rtp.c:2571 ast_rtp_raw_write: Difference is 1912, ms is 259
[May 24 15:24:15] DEBUG[3579]: channel.c:2030 ast_settimeout: Scheduling timer at 160 sample intervals
[May 24 15:24:15]     -- <SIP/2400-08221068> Playing 'vm-msgsaved' (language 'fr')
[May 24 15:24:15] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[May 24 15:24:15] DEBUG[3579]: rtp.c:727 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[May 24 15:24:17] DEBUG[3579]: channel.c:2030 ast_settimeout: Scheduling timer at 35 sample intervals
[May 24 15:24:17] DEBUG[3579]: channel.c:2030 ast_settimeout: Scheduling timer at 0 sample intervals
[May 24 15:24:17] DEBUG[3579]: channel.c:2030 ast_settimeout: Scheduling timer at 0 sample intervals
[May 24 15:24:17] DEBUG[3579]: app_voicemail.c:2407 imap_store_file: Storing file '/var/spool/asterisk/voicemail/default/2500/temp/msg-001', format 'gsm'
[May 24 15:24:17] DEBUG[3579]: app_voicemail.c:1972 make_email_file: newtmp: /var/spool/asterisk/voicemail/default/2500/tmp/S1LhpK
[May 24 15:24:17] WARNING[3579]: app_voicemail.c:1701 base_encode: Failed to open log file: /var/spool/asterisk/voicemail/default/2500/temp/msg-001.gsm: No such file or directory
[May 24 15:24:17] ERROR[3579]: app_voicemail.c:4670 init_mailstream: vm_state is NULL!