-- Executing [*98@extensions:1] Answer("SIP/5050-085fa8d0", "") in new stack
[Feb  7 10:19:18] DEBUG[16363]: devicestate.c:382 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5050-085fa8d0
[Feb  7 10:19:18] DEBUG[16363]: chan_sip.c:3579 sip_answer: SIP answering channel: SIP/5050-085fa8d0
[Feb  7 10:19:18] DEBUG[16363]: chan_sip.c:6519 transmit_response_with_sdp: Setting framing from config on incoming call
[Feb  7 10:19:18] DEBUG[16363]: chan_sip.c:6294 add_sdp: ** Our capability: 0xe (gsm|ulaw|alaw) Video flag: True
[Feb  7 10:19:18] DEBUG[16363]: chan_sip.c:6295 add_sdp: ** Our prefcodec: 0x0 (nothing) 
[Feb  7 10:19:18] DEBUG[16363]: chan_sip.c:6420 add_sdp: -- Done with adding codecs to SDP
[Feb  7 10:19:18] DEBUG[16363]: channel.c:2291 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1)
[Feb  7 10:19:18] DEBUG[16363]: chan_sip.c:6464 add_sdp: Done building SDP. Settling with this capability: 0xe (gsm|ulaw|alaw)
[Feb  7 10:19:18] DEBUG[16363]: pbx.c:1693 pbx_extension_helper: Launching 'Set'
    -- Executing [*98@extensions:2] Set("SIP/5050-085fa8d0", "CHANNEL(language)=pt_BR") in new stack
[Feb  7 10:19:18] DEBUG[16363]: pbx.c:1693 pbx_extension_helper: Launching 'VoiceMailMain'
    -- Executing [*98@extensions:3] VoiceMailMain("SIP/5050-085fa8d0", "@default") in new stack
[Feb  7 10:19:18] DEBUG[16363]: channel.c:2755 set_format: Set channel SIP/5050-085fa8d0 to write format slin
[Feb  7 10:19:18] DEBUG[16363]: rtp.c:2757 ast_rtp_write: Ooh, format changed from unknown to ulaw
[Feb  7 10:19:18] DEBUG[16363]: rtp.c:2774 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160
    -- <SIP/5050-085fa8d0> Playing 'vm-login' (language 'pt_BR')
[Feb  7 10:19:18] DEBUG[16363]: devicestate.c:244 ast_device_state: No provider found, checking channel drivers for SIP - 5050
[Feb  7 10:19:18] DEBUG[16363]: chan_sip.c:15405 sip_devicestate: Checking device state for peer 5050
[Feb  7 10:19:18] DEBUG[16363]: devicestate.c:366 do_state_change: Changing state for SIP/5050 - state 1 (Not in use)
[Feb  7 10:19:18] DEBUG[16363]: devicestate.c:244 ast_device_state: No provider found, checking channel drivers for SIP - 5050
[Feb  7 10:19:18] DEBUG[16363]: chan_sip.c:15405 sip_devicestate: Checking device state for peer 5050
[Feb  7 10:19:18] DEBUG[16363]: devicestate.c:366 do_state_change: Changing state for SIP/5050 - state 1 (Not in use)
[Feb  7 10:19:18] DEBUG[16363]: app_queue.c:568 changethread: Device 'SIP/5050' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Feb  7 10:19:18] DEBUG[16363]: app_queue.c:568 changethread: Device 'SIP/5050' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Feb  7 10:19:18] DEBUG[16363]: chan_sip.c:4478 find_call: = Found Their Call ID: 5049ED7A-1DD2-11B2-A1FF-AFEAB2037000@172.16.0.192 Their Tag 2620032030430651053 Our tag: as6a336706
[Feb  7 10:19:18] DEBUG[16363]: chan_sip.c:14779 handle_request: **** Received ACK (6) - Command in SIP ACK
[Feb  7 10:19:18] DEBUG[16363]: chan_sip.c:2141 __sip_ack: Stopping retransmission on '5049ED7A-1DD2-11B2-A1FF-AFEAB2037000@172.16.0.192' of Response 2: Match Found
  == Connect attempt from '127.0.0.1' unable to authenticate
[Feb  7 10:19:19] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Feb  7 10:19:19] DEBUG[16363]: rtp.c:644 send_dtmf: Sending dtmf: 53 (5), at 172.16.0.192
[Feb  7 10:19:19] DTMF[16363]: channel.c:2162 __ast_read: DTMF begin '5' received on SIP/5050-085fa8d0
[Feb  7 10:19:19] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Feb  7 10:19:19] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Feb  7 10:19:19] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Feb  7 10:19:19] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Feb  7 10:19:19] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Feb  7 10:19:19] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Feb  7 10:19:19] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Feb  7 10:19:19] DEBUG[16363]: rtp.c:644 send_dtmf: Sending dtmf: 53 (5), at 172.16.0.192
[Feb  7 10:19:19] DTMF[16363]: channel.c:2135 __ast_read: DTMF end '5' received on SIP/5050-085fa8d0
[Feb  7 10:19:19] DEBUG[16363]: channel.c:2755 set_format: Set channel SIP/5050-085fa8d0 to write format ulaw
[Feb  7 10:19:19] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Feb  7 10:19:19] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Feb  7 10:19:19] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Feb  7 10:19:19] DEBUG[16363]: rtp.c:644 send_dtmf: Sending dtmf: 48 (0), at 172.16.0.192
[Feb  7 10:19:19] DTMF[16363]: channel.c:2162 __ast_read: DTMF begin '0' received on SIP/5050-085fa8d0
[Feb  7 10:19:19] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Feb  7 10:19:19] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Feb  7 10:19:19] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Feb  7 10:19:19] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Feb  7 10:19:19] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Feb  7 10:19:19] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Feb  7 10:19:19] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Feb  7 10:19:19] DEBUG[16363]: rtp.c:644 send_dtmf: Sending dtmf: 48 (0), at 172.16.0.192
[Feb  7 10:19:19] DTMF[16363]: channel.c:2135 __ast_read: DTMF end '0' received on SIP/5050-085fa8d0
[Feb  7 10:19:19] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Feb  7 10:19:19] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Feb  7 10:19:20] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Feb  7 10:19:20] DEBUG[16363]: rtp.c:644 send_dtmf: Sending dtmf: 53 (5), at 172.16.0.192
[Feb  7 10:19:20] DTMF[16363]: channel.c:2162 __ast_read: DTMF begin '5' received on SIP/5050-085fa8d0
[Feb  7 10:19:20] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Feb  7 10:19:20] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Feb  7 10:19:20] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Feb  7 10:19:20] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Feb  7 10:19:20] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Feb  7 10:19:20] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Feb  7 10:19:20] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Feb  7 10:19:20] DEBUG[16363]: rtp.c:644 send_dtmf: Sending dtmf: 53 (5), at 172.16.0.192
[Feb  7 10:19:20] DTMF[16363]: channel.c:2135 __ast_read: DTMF end '5' received on SIP/5050-085fa8d0
[Feb  7 10:19:20] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Feb  7 10:19:20] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Feb  7 10:19:20] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Feb  7 10:19:20] DEBUG[16363]: rtp.c:644 send_dtmf: Sending dtmf: 48 (0), at 172.16.0.192
[Feb  7 10:19:20] DTMF[16363]: channel.c:2162 __ast_read: DTMF begin '0' received on SIP/5050-085fa8d0
[Feb  7 10:19:20] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Feb  7 10:19:20] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Feb  7 10:19:20] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Feb  7 10:19:20] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Feb  7 10:19:20] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Feb  7 10:19:20] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Feb  7 10:19:20] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Feb  7 10:19:20] DEBUG[16363]: rtp.c:644 send_dtmf: Sending dtmf: 48 (0), at 172.16.0.192
[Feb  7 10:19:20] DTMF[16363]: channel.c:2135 __ast_read: DTMF end '0' received on SIP/5050-085fa8d0
[Feb  7 10:19:20] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Feb  7 10:19:20] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000000 (len = 4)
[Feb  7 10:19:20] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 10:19:20] DEBUG[16363]: rtp.c:644 send_dtmf: Sending dtmf: 35 (#), at 172.16.0.192
[Feb  7 10:19:20] DTMF[16363]: channel.c:2162 __ast_read: DTMF begin '#' received on SIP/5050-085fa8d0
[Feb  7 10:19:20] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 10:19:20] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 10:19:20] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 10:19:20] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 10:19:20] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 10:19:20] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 10:19:20] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 10:19:20] DEBUG[16363]: rtp.c:644 send_dtmf: Sending dtmf: 35 (#), at 172.16.0.192
[Feb  7 10:19:20] DTMF[16363]: channel.c:2135 __ast_read: DTMF end '#' received on SIP/5050-085fa8d0
[Feb  7 10:19:20] DEBUG[16363]: app_voicemail.c:6141 vm_authenticate: Before find user for mailbox 5050
[Feb  7 10:19:20] DEBUG[16363]: channel.c:2755 set_format: Set channel SIP/5050-085fa8d0 to write format slin
[Feb  7 10:19:20] DEBUG[16363]: rtp.c:2626 ast_rtp_raw_write: Difference is 10400, ms is 1320
    -- <SIP/5050-085fa8d0> Playing 'vm-password' (language 'pt_BR')
[Feb  7 10:19:20] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 10:19:20] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 10:19:21] DEBUG[16363]: channel.c:2755 set_format: Set channel SIP/5050-085fa8d0 to write format ulaw
[Feb  7 10:19:21] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Feb  7 10:19:21] DEBUG[16363]: rtp.c:644 send_dtmf: Sending dtmf: 49 (1), at 172.16.0.192
[Feb  7 10:19:21] DTMF[16363]: channel.c:2162 __ast_read: DTMF begin '1' received on SIP/5050-085fa8d0
[Feb  7 10:19:21] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Feb  7 10:19:21] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Feb  7 10:19:21] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Feb  7 10:19:21] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Feb  7 10:19:21] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Feb  7 10:19:21] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Feb  7 10:19:21] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Feb  7 10:19:21] DEBUG[16363]: rtp.c:644 send_dtmf: Sending dtmf: 49 (1), at 172.16.0.192
[Feb  7 10:19:21] DTMF[16363]: channel.c:2135 __ast_read: DTMF end '1' received on SIP/5050-085fa8d0
[Feb  7 10:19:21] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Feb  7 10:19:21] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Feb  7 10:19:22] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 10:19:22] DEBUG[16363]: rtp.c:644 send_dtmf: Sending dtmf: 35 (#), at 172.16.0.192
[Feb  7 10:19:22] DTMF[16363]: channel.c:2162 __ast_read: DTMF begin '#' received on SIP/5050-085fa8d0
[Feb  7 10:19:22] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 10:19:22] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 10:19:22] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 10:19:22] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 10:19:22] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 10:19:22] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 10:19:22] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 10:19:22] DEBUG[16363]: rtp.c:644 send_dtmf: Sending dtmf: 35 (#), at 172.16.0.192
[Feb  7 10:19:22] DTMF[16363]: channel.c:2135 __ast_read: DTMF end '#' received on SIP/5050-085fa8d0
[Feb  7 10:19:22] DEBUG[16363]: app_voicemail.c:6317 vm_execmain: After vm_authenticate
[Feb  7 10:19:22] DEBUG[16363]: app_voicemail.c:6353 vm_execmain: Before open_mailbox
[Feb  7 10:19:22] DEBUG[16363]: app.c:965 ast_lock_path: Locked path '/var/spool/asterisk/voicemail/default/5050/Old'
[Feb  7 10:19:22] DEBUG[16363]: app.c:986 ast_unlock_path: Unlocked path '/var/spool/asterisk/voicemail/default/5050/Old'
[Feb  7 10:19:22] DEBUG[16363]: app_voicemail.c:6359 vm_execmain: Number of old messages: 1
[Feb  7 10:19:22] DEBUG[16363]: app.c:965 ast_lock_path: Locked path '/var/spool/asterisk/voicemail/default/5050/INBOX'
[Feb  7 10:19:22] DEBUG[16363]: app.c:986 ast_unlock_path: Unlocked path '/var/spool/asterisk/voicemail/default/5050/INBOX'
[Feb  7 10:19:22] DEBUG[16363]: app_voicemail.c:6366 vm_execmain: Number of new messages: 0
[Feb  7 10:19:22] DEBUG[16363]: app.c:965 ast_lock_path: Locked path '/var/spool/asterisk/voicemail/default/5050/Old'
[Feb  7 10:19:22] DEBUG[16363]: app.c:986 ast_unlock_path: Unlocked path '/var/spool/asterisk/voicemail/default/5050/Old'
[Feb  7 10:19:22] DEBUG[16363]: channel.c:2755 set_format: Set channel SIP/5050-085fa8d0 to write format slin
[Feb  7 10:19:22] DEBUG[16363]: rtp.c:2626 ast_rtp_raw_write: Difference is 4848, ms is 626
    -- <SIP/5050-085fa8d0> Playing 'vm-youhave' (language 'pt_BR')
[Feb  7 10:19:22] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 10:19:22] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 10:19:23] DEBUG[16363]: channel.c:2755 set_format: Set channel SIP/5050-085fa8d0 to write format ulaw
[Feb  7 10:19:23] DEBUG[16363]: channel.c:2755 set_format: Set channel SIP/5050-085fa8d0 to write format slin
    -- <SIP/5050-085fa8d0> Playing 'digits/1F' (language 'pt_BR')
[Feb  7 10:19:23] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Feb  7 10:19:23] DEBUG[16363]: rtp.c:644 send_dtmf: Sending dtmf: 49 (1), at 172.16.0.192
[Feb  7 10:19:23] DTMF[16363]: channel.c:2162 __ast_read: DTMF begin '1' received on SIP/5050-085fa8d0
[Feb  7 10:19:23] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Feb  7 10:19:23] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Feb  7 10:19:23] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Feb  7 10:19:23] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Feb  7 10:19:23] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Feb  7 10:19:23] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Feb  7 10:19:23] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Feb  7 10:19:23] DEBUG[16363]: rtp.c:644 send_dtmf: Sending dtmf: 49 (1), at 172.16.0.192
[Feb  7 10:19:23] DTMF[16363]: channel.c:2135 __ast_read: DTMF end '1' received on SIP/5050-085fa8d0
[Feb  7 10:19:23] DEBUG[16363]: channel.c:2755 set_format: Set channel SIP/5050-085fa8d0 to write format ulaw
[Feb  7 10:19:23] DEBUG[16363]: channel.c:2755 set_format: Set channel SIP/5050-085fa8d0 to write format slin
    -- <SIP/5050-085fa8d0> Playing 'vm-first' (language 'pt_BR')
[Feb  7 10:19:23] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Feb  7 10:19:23] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Feb  7 10:19:24] DEBUG[16363]: channel.c:2755 set_format: Set channel SIP/5050-085fa8d0 to write format ulaw
[Feb  7 10:19:24] DEBUG[16363]: channel.c:2755 set_format: Set channel SIP/5050-085fa8d0 to write format slin
    -- <SIP/5050-085fa8d0> Playing 'vm-message' (language 'pt_BR')
[Feb  7 10:19:25] DEBUG[16363]: channel.c:2755 set_format: Set channel SIP/5050-085fa8d0 to write format ulaw
[Feb  7 10:19:25] WARNING[16363]: app_voicemail.c:1101 retrieve_file: SQL Get Data error!
[SELECT * FROM tb_voicemail_messages WHERE dir=? AND msgnum=?]

  == Parsing '/var/spool/asterisk/voicemail/default/5050/Old/msg0000.txt': [Feb  7 10:19:25] DEBUG[16363]: config.c:851 config_text_file_load: Parsing /var/spool/asterisk/voicemail/default/5050/Old/msg0000.txt
Found
[Feb  7 10:19:25] DEBUG[16363]: channel.c:2755 set_format: Set channel SIP/5050-085fa8d0 to write format gsm
    -- <SIP/5050-085fa8d0> Playing '/var/spool/asterisk/voicemail/default/5050/Old/msg0000' (language 'pt_BR')
[Feb  7 10:19:26] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Feb  7 10:19:26] DEBUG[16363]: rtp.c:644 send_dtmf: Sending dtmf: 56 (8), at 172.16.0.192
[Feb  7 10:19:26] DTMF[16363]: channel.c:2162 __ast_read: DTMF begin '8' received on SIP/5050-085fa8d0
[Feb  7 10:19:26] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Feb  7 10:19:26] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Feb  7 10:19:26] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Feb  7 10:19:26] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Feb  7 10:19:26] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Feb  7 10:19:26] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Feb  7 10:19:26] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Feb  7 10:19:26] DEBUG[16363]: rtp.c:644 send_dtmf: Sending dtmf: 56 (8), at 172.16.0.192
[Feb  7 10:19:26] DTMF[16363]: channel.c:2135 __ast_read: DTMF end '8' received on SIP/5050-085fa8d0
[Feb  7 10:19:26] DEBUG[16363]: channel.c:2755 set_format: Set channel SIP/5050-085fa8d0 to write format ulaw
[Feb  7 10:19:26] DEBUG[16363]: channel.c:2755 set_format: Set channel SIP/5050-085fa8d0 to write format slin
    -- <SIP/5050-085fa8d0> Playing 'vm-extension' (language 'pt_BR')
[Feb  7 10:19:26] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Feb  7 10:19:26] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000008 (len = 4)
[Feb  7 10:19:27] DEBUG[16363]: channel.c:2755 set_format: Set channel SIP/5050-085fa8d0 to write format ulaw
[Feb  7 10:19:28] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Feb  7 10:19:28] DEBUG[16363]: rtp.c:644 send_dtmf: Sending dtmf: 49 (1), at 172.16.0.192
[Feb  7 10:19:28] DTMF[16363]: channel.c:2162 __ast_read: DTMF begin '1' received on SIP/5050-085fa8d0
[Feb  7 10:19:28] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Feb  7 10:19:28] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Feb  7 10:19:28] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Feb  7 10:19:28] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Feb  7 10:19:28] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Feb  7 10:19:28] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Feb  7 10:19:28] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Feb  7 10:19:28] DEBUG[16363]: rtp.c:644 send_dtmf: Sending dtmf: 49 (1), at 172.16.0.192
[Feb  7 10:19:28] DTMF[16363]: channel.c:2135 __ast_read: DTMF end '1' received on SIP/5050-085fa8d0
[Feb  7 10:19:28] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Feb  7 10:19:28] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Feb  7 10:19:28] DEBUG[16363]: manager.c:2065 process_message: Manager received command 'Challenge'
[Feb  7 10:19:28] DEBUG[16363]: manager.c:2065 process_message: Manager received command 'Login'
  == Parsing '/etc/asterisk/manager.conf': [Feb  7 10:19:28] DEBUG[16363]: config.c:851 config_text_file_load: Parsing /etc/asterisk/manager.conf
Found
[Feb  7 10:19:28] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Feb  7 10:19:28] DEBUG[16363]: rtp.c:644 send_dtmf: Sending dtmf: 49 (1), at 172.16.0.192
[Feb  7 10:19:28] DTMF[16363]: channel.c:2162 __ast_read: DTMF begin '1' received on SIP/5050-085fa8d0
[Feb  7 10:19:28] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Feb  7 10:19:28] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Feb  7 10:19:28] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Feb  7 10:19:28] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Feb  7 10:19:28] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Feb  7 10:19:28] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Feb  7 10:19:28] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Feb  7 10:19:28] DEBUG[16363]: rtp.c:644 send_dtmf: Sending dtmf: 49 (1), at 172.16.0.192
[Feb  7 10:19:28] DTMF[16363]: channel.c:2135 __ast_read: DTMF end '1' received on SIP/5050-085fa8d0
[Feb  7 10:19:28] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Feb  7 10:19:28] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000001 (len = 4)
[Feb  7 10:19:28] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Feb  7 10:19:28] DEBUG[16363]: rtp.c:644 send_dtmf: Sending dtmf: 53 (5), at 172.16.0.192
[Feb  7 10:19:28] DTMF[16363]: channel.c:2162 __ast_read: DTMF begin '5' received on SIP/5050-085fa8d0
[Feb  7 10:19:28] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Feb  7 10:19:28] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Feb  7 10:19:28] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Feb  7 10:19:28] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Feb  7 10:19:28] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Feb  7 10:19:28] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Feb  7 10:19:28] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Feb  7 10:19:28] DEBUG[16363]: rtp.c:644 send_dtmf: Sending dtmf: 53 (5), at 172.16.0.192
[Feb  7 10:19:28] DTMF[16363]: channel.c:2135 __ast_read: DTMF end '5' received on SIP/5050-085fa8d0
[Feb  7 10:19:28] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
[Feb  7 10:19:28] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4)
  == Connect attempt from '127.0.0.1' unable to authenticate
[Feb  7 10:19:29] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 10:19:29] DEBUG[16363]: rtp.c:644 send_dtmf: Sending dtmf: 35 (#), at 172.16.0.192
[Feb  7 10:19:29] DTMF[16363]: channel.c:2162 __ast_read: DTMF begin '#' received on SIP/5050-085fa8d0
[Feb  7 10:19:29] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 10:19:29] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 10:19:29] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 10:19:29] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 10:19:29] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 10:19:29] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 10:19:29] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 10:19:29] DEBUG[16363]: rtp.c:644 send_dtmf: Sending dtmf: 35 (#), at 172.16.0.192
[Feb  7 10:19:29] DTMF[16363]: channel.c:2135 __ast_read: DTMF end '#' received on SIP/5050-085fa8d0
[Feb  7 10:19:29] WARNING[16363]: app_voicemail.c:1101 retrieve_file: SQL Get Data error!
[SELECT * FROM tb_voicemail_messages WHERE dir=? AND msgnum=?]

[Feb  7 10:19:29] DEBUG[16363]: channel.c:2755 set_format: Set channel SIP/5050-085fa8d0 to write format slin
[Feb  7 10:19:29] DEBUG[16363]: rtp.c:2626 ast_rtp_raw_write: Difference is 18760, ms is 2365
    -- <SIP/5050-085fa8d0> Playing 'vm-forwardoptions' (language 'pt_BR')
[Feb  7 10:19:29] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 10:19:29] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4)
[Feb  7 10:19:31] DEBUG[16363]: chan_sip.c:4478 find_call: = No match Their Call ID: 5049ED7A-1DD2-11B2-A1FF-AFEAB2037000@172.16.0.192 Their Tag 2620032030430651053 Our tag: as6a336706
[Feb  7 10:19:31] DEBUG[16363]: chan_sip.c:4478 find_call: = Found Their Call ID: D392B06A-1DD1-11B2-A1FD-AFEAB2037000@172.16.0.192 Their Tag 2619724897608873529 Our tag: as6180d8c0
[Feb  7 10:19:31] DEBUG[16363]: chan_sip.c:14779 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS
[Feb  7 10:19:32] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Feb  7 10:19:32] DEBUG[16363]: rtp.c:644 send_dtmf: Sending dtmf: 50 (2), at 172.16.0.192
[Feb  7 10:19:32] DTMF[16363]: channel.c:2162 __ast_read: DTMF begin '2' received on SIP/5050-085fa8d0
[Feb  7 10:19:32] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Feb  7 10:19:32] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Feb  7 10:19:32] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Feb  7 10:19:32] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Feb  7 10:19:33] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Feb  7 10:19:33] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Feb  7 10:19:33] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Feb  7 10:19:33] DEBUG[16363]: rtp.c:644 send_dtmf: Sending dtmf: 50 (2), at 172.16.0.192
[Feb  7 10:19:33] DTMF[16363]: channel.c:2135 __ast_read: DTMF end '2' received on SIP/5050-085fa8d0
[Feb  7 10:19:33] DEBUG[16363]: channel.c:2755 set_format: Set channel SIP/5050-085fa8d0 to write format ulaw
[Feb  7 10:19:33] NOTICE[16363]: app_voicemail.c:2635 copy_message: Copying message from 5050@default to 115@default
[Feb  7 10:19:33] DEBUG[16363]: app.c:965 ast_lock_path: Locked path '/var/spool/asterisk/voicemail/default/115/INBOX'
[Feb  7 10:19:33] WARNING[16363]: app_voicemail.c:1290 delete_file: SQL Execute error!
[DELETE FROM tb_voicemail_messages WHERE dir=? AND msgnum=?]

[Feb  7 10:19:33] DEBUG[16363]: app.c:986 ast_unlock_path: Unlocked path '/var/spool/asterisk/voicemail/default/115/INBOX'
[Feb  7 10:19:33] DEBUG[16363]: app_voicemail.c:2029 sendmail: Attaching file '/var/spool/asterisk/voicemail/default/115/INBOX/msg0000', format 'WAV', uservm is '0', global is 0
[Feb  7 10:19:33] DEBUG[16363]: devicestate.c:382 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel **Unknown**
[Feb  7 10:19:33] DEBUG[16363]: devicestate.c:382 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel **Unknown**
[Feb  7 10:19:33] DEBUG[16363]: devicestate.c:382 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel **Unknown**
[Feb  7 10:19:33] DEBUG[16363]: app_voicemail.c:2041 sendmail: Sent mail to 115@net.net with command 'sendmail -t'
[Feb  7 10:19:33] DEBUG[16363]: devicestate.c:239 ast_device_state: Checking if I can find provider for "**Unknown**" - number: (null)
[Feb  7 10:19:33] DEBUG[16363]: devicestate.c:310 getproviderstate: Checking provider SLA with **Unknown**
[Feb  7 10:19:33] DEBUG[16363]: devicestate.c:310 getproviderstate: Checking provider Meetme with **Unknown**
[Feb  7 10:19:33] DEBUG[16363]: devicestate.c:310 getproviderstate: Checking provider Park with **Unknown**
[Feb  7 10:19:33] DEBUG[16363]: devicestate.c:366 do_state_change: Changing state for **Unknown** - state 4 (Invalid)
[Feb  7 10:19:33] DEBUG[16363]: devicestate.c:239 ast_device_state: Checking if I can find provider for "**Unknown**" - number: (null)
[Feb  7 10:19:33] DEBUG[16363]: devicestate.c:310 getproviderstate: Checking provider SLA with **Unknown**
[Feb  7 10:19:33] DEBUG[16363]: devicestate.c:310 getproviderstate: Checking provider Meetme with **Unknown**
[Feb  7 10:19:33] DEBUG[16363]: devicestate.c:310 getproviderstate: Checking provider Park with **Unknown**
[Feb  7 10:19:33] DEBUG[16363]: devicestate.c:366 do_state_change: Changing state for **Unknown** - state 4 (Invalid)
[Feb  7 10:19:33] DEBUG[16363]: devicestate.c:239 ast_device_state: Checking if I can find provider for "**Unknown**" - number: (null)
[Feb  7 10:19:33] DEBUG[16363]: devicestate.c:310 getproviderstate: Checking provider SLA with **Unknown**
[Feb  7 10:19:33] DEBUG[16363]: devicestate.c:310 getproviderstate: Checking provider Meetme with **Unknown**
[Feb  7 10:19:33] DEBUG[16363]: devicestate.c:310 getproviderstate: Checking provider Park with **Unknown**
[Feb  7 10:19:33] DEBUG[16363]: devicestate.c:366 do_state_change: Changing state for **Unknown** - state 4 (Invalid)
[Feb  7 10:19:33] DEBUG[16363]: channel.c:2755 set_format: Set channel SIP/5050-085fa8d0 to write format slin
    -- <SIP/5050-085fa8d0> Playing 'vm-msgsaved' (language 'pt_BR')
[Feb  7 10:19:33] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Feb  7 10:19:33] DEBUG[16363]: rtp.c:795 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4)
[Feb  7 10:19:35] DEBUG[16363]: channel.c:2755 set_format: Set channel SIP/5050-085fa8d0 to write format ulaw
[Feb  7 10:19:35] DEBUG[16363]: channel.c:2755 set_format: Set channel SIP/5050-085fa8d0 to write format slin
    -- <SIP/5050-085fa8d0> Playing 'vm-advopts' (language 'pt_BR')