May 31 07:36:10] DEBUG[2270] chan_sip.c: Setting NAT on RTP to Off [May 31 07:36:10] DEBUG[2270] chan_sip.c: Allocating new SIP dialog for 1536432007-839465162063105682@208.51.102.30 - INVITE (With RTP) [May 31 07:36:10] DEBUG[2270] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [May 31 07:36:10] DEBUG[2270] chan_sip.c: Setting NAT on RTP to Off [May 31 07:36:10] DEBUG[2270] chan_sip.c: T38 state changed to 0 on channel [May 31 07:36:10] DEBUG[2270] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [May 31 07:36:10] DEBUG[2270] chan_sip.c: Checking SIP call limits for device [May 31 07:36:10] DEBUG[2270] chan_sip.c: Updating call counter for incoming call [May 31 07:36:10] DEBUG[2270] chan_sip.c: *** Our native formats are 0x4 (ulaw) [May 31 07:36:10] DEBUG[2270] chan_sip.c: *** Joint capabilities are 0x4 (ulaw) [May 31 07:36:10] DEBUG[2270] chan_sip.c: *** Our capabilities are 0x8000d (g723|ulaw|alaw|h263) [May 31 07:36:10] DEBUG[2270] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [May 31 07:36:10] DEBUG[2270] chan_sip.c: This channel will not be able to handle video. [May 31 07:36:10] DEBUG[2270] chan_sip.c: build_route: Contact hop: [May 31 07:36:10] DEBUG[2270] chan_sip.c: SIP/5080-09587fa8: New call is still down.... Trying... [May 31 07:36:10] DEBUG[2270] devicestate.c: Notification of state change to be queued on device/channel SIP/5080-09587fa8 [May 31 07:36:10] DEBUG[2267] devicestate.c: No provider found, checking channel drivers for SIP - 5080 [May 31 07:36:10] DEBUG[2267] chan_sip.c: Checking device state for peer 5080 [May 31 07:36:10] DEBUG[2267] devicestate.c: Changing state for SIP/5080 - state 4 (Invalid) [May 31 07:36:10] VERBOSE[9864] logger.c: [May 31 07:36:10] -- Executing NoOp("SIP/5080-09587fa8", "EXTEN is 18666777934") [May 31 07:36:10] VERBOSE[9864] logger.c: [May 31 07:36:10] -- Executing NoOp("SIP/5080-09587fa8", "CHANNEL is SIP/5080-09587fa8") [May 31 07:36:10] VERBOSE[9864] logger.c: [May 31 07:36:10] -- Executing NoOp("SIP/5080-09587fa8", "CONTEXT is inbound") [May 31 07:36:10] VERBOSE[9864] logger.c: [May 31 07:36:10] -- Executing NoOp("SIP/5080-09587fa8", "CALLERIDNUM is ") [May 31 07:36:10] VERBOSE[9864] logger.c: [May 31 07:36:10] -- Executing NoOp("SIP/5080-09587fa8", "CALLERID is ") [May 31 07:36:10] VERBOSE[9864] logger.c: [May 31 07:36:10] -- Executing NoOp("SIP/5080-09587fa8", "Sending to voicemailbox '18666777934'") [May 31 07:36:10] VERBOSE[9864] logger.c: [May 31 07:36:10] -- Executing Answer("SIP/5080-09587fa8", "") [May 31 07:36:10] DEBUG[9864] devicestate.c: Notification of state change to be queued on device/channel SIP/5080-09587fa8 [May 31 07:36:10] DEBUG[9864] chan_sip.c: SIP answering channel: SIP/5080-09587fa8 [May 31 07:36:10] DEBUG[9864] chan_sip.c: Setting framing from config on incoming call [May 31 07:36:10] DEBUG[9864] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True [May 31 07:36:10] DEBUG[9864] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [May 31 07:36:10] DEBUG[9864] chan_sip.c: -- Done with adding codecs to SDP [May 31 07:36:10] DEBUG[9864] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [May 31 07:36:10] DEBUG[9864] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [May 31 07:36:10] DEBUG[2267] devicestate.c: No provider found, checking channel drivers for SIP - 5080 [May 31 07:36:10] DEBUG[2267] chan_sip.c: Checking device state for peer 5080 [May 31 07:36:10] DEBUG[2267] devicestate.c: Changing state for SIP/5080 - state 4 (Invalid) [May 31 07:36:10] VERBOSE[9864] logger.c: [May 31 07:36:10] -- Executing Voicemail("SIP/5080-09587fa8", "u18666777934@customer") [May 31 07:36:10] DEBUG[9864] app_voicemail.c: Before find_user [May 31 07:36:10] DEBUG[9864] channel.c: Set channel SIP/5080-09587fa8 to write format gsm [May 31 07:36:10] DEBUG[9864] rtp.c: Ooh, format changed from unknown to ulaw [May 31 07:36:10] DEBUG[9864] rtp.c: Created smoother: format: 4 ms: 20 len: 160 [May 31 07:36:10] VERBOSE[9864] logger.c: [May 31 07:36:10] -- Playing '/var/spool/asterisk/voicemail/customer/18666777934/unavail' (language 'en') [May 31 07:36:10] DEBUG[2270] chan_sip.c: = Found Their Call ID: 1536432007-839465162063105682@208.51.102.30 Their Tag GR52RWG346-34 Our tag: as41ff4030 [May 31 07:36:10] DEBUG[2270] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [May 31 07:36:10] DEBUG[2270] chan_sip.c: Stopping retransmission on '1536432007-839465162063105682@208.51.102.30' of Response 1: Match Not Found [May 31 07:36:12] DEBUG[9864] channel.c: Set channel SIP/5080-09587fa8 to write format ulaw [May 31 07:36:12] VERBOSE[9864] logger.c: [May 31 07:36:12] -- Playing 'vm-intro' (language 'en') [May 31 07:36:18] VERBOSE[9864] logger.c: [May 31 07:36:18] -- Playing 'beep' (language 'en') [May 31 07:36:18] VERBOSE[9864] logger.c: [May 31 07:36:18] -- Recording the message [May 31 07:36:18] DEBUG[9864] app.c: play_and_record: , /var/spool/asterisk/voicemail/customer/18666777934/tmp/mCD0QO, 'wav49|wav' [May 31 07:36:18] DEBUG[9864] app.c: Recording Formats: sfmts=wav49 [May 31 07:36:18] VERBOSE[9864] logger.c: [May 31 07:36:18] -- x=0, open writing: /var/spool/asterisk/voicemail/customer/18666777934/tmp/mCD0QO format: wav49, 0x9586cb8 [May 31 07:36:18] VERBOSE[9864] logger.c: [May 31 07:36:18] -- x=1, open writing: /var/spool/asterisk/voicemail/customer/18666777934/tmp/mCD0QO format: wav, 0x9584710 [May 31 07:36:18] DEBUG[9864] channel.c: Set channel SIP/5080-09587fa8 to read format slin [May 31 07:36:20] DEBUG[9864] app.c: One waitfor failed, trying another [May 31 07:36:22] WARNING[9864] app.c: No audio available on SIP/5080-09587fa8?? [May 31 07:36:22] VERBOSE[9864] logger.c: [May 31 07:36:22] -- User hung up [May 31 07:36:22] DEBUG[9864] channel.c: Set channel SIP/5080-09587fa8 to read format ulaw [May 31 07:36:22] DEBUG[9864] app.c: Locked path '/var/spool/asterisk/voicemail/customer/18666777934/INBOX' [May 31 07:36:22] DEBUG[9864] app.c: Unlocked path '/var/spool/asterisk/voicemail/customer/18666777934/INBOX' [May 31 07:36:22] VERBOSE[9864] logger.c: [May 31 07:36:22] == Parsing '/var/spool/asterisk/voicemail/customer/18666777934/INBOX/msg0014.txt': [May 31 07:36:22] DEBUG[9864] config.c: Parsing /var/spool/asterisk/voicemail/customer/18666777934/INBOX/msg0014.txt [May 31 07:36:22] VERBOSE[9864] logger.c: [May 31 07:36:22] Found [May 31 07:36:22] DEBUG[9864] app_voicemail.c: Attaching file '/var/spool/asterisk/voicemail/customer/18666777934/INBOX/msg0014', format 'WAV', uservm is '2048', global is 2048 [May 31 07:36:22] DEBUG[9864] devicestate.c: Notification of state change to be queued on device/channel **Unknown** [May 31 07:36:22] DEBUG[9864] devicestate.c: Notification of state change to be queued on device/channel **Unknown** [May 31 07:36:22] DEBUG[9864] devicestate.c: Notification of state change to be queued on device/channel **Unknown** [May 31 07:36:22] DEBUG[9864] app_voicemail.c: newtmp: /var/spool/asterisk/voicemail/customer/18666777934/tmp/1DiyQA [May 31 07:36:22] DEBUG[9864] app_voicemail.c: Sent mail to mbaker@i2telecom.com with command '/usr/sbin/sendmail -t' [May 31 07:36:22] DEBUG[2267] devicestate.c: Checking if I can find provider for "**Unknown**" - number: (null) [May 31 07:36:22] DEBUG[2267] devicestate.c: Checking provider Park with **Unknown** [May 31 07:36:22] DEBUG[2267] devicestate.c: Changing state for **Unknown** - state 4 (Invalid) [May 31 07:36:22] DEBUG[2267] devicestate.c: Checking if I can find provider for "**Unknown**" - number: (null) [May 31 07:36:22] DEBUG[2267] devicestate.c: Checking provider Park with **Unknown** [May 31 07:36:22] DEBUG[2267] devicestate.c: Changing state for **Unknown** - state 4 (Invalid) [May 31 07:36:22] DEBUG[2267] devicestate.c: Checking if I can find provider for "**Unknown**" - number: (null) [May 31 07:36:22] DEBUG[2267] devicestate.c: Checking provider Park with **Unknown** [May 31 07:36:22] DEBUG[2267] devicestate.c: Changing state for **Unknown** - state 4 (Invalid) [May 31 07:36:22] DEBUG[9864] pbx.c: Spawn extension (inbound,18666777934,8) exited non-zero on 'SIP/5080-09587fa8' [May 31 07:36:22] VERBOSE[9864] logger.c: [May 31 07:36:22] == Spawn extension (inbound, 18666777934, 8) exited non-zero on 'SIP/5080-09587fa8' [May 31 07:36:22] VERBOSE[9864] logger.c: [May 31 07:36:22] > cdr_odbc: Connected to astvmail [May 31 07:36:22] VERBOSE[9864] logger.c: [May 31 07:36:22] > cdr_odbc: Query Successful! [May 31 07:36:22] DEBUG[9864] channel.c: Hanging up channel 'SIP/5080-09587fa8' [May 31 07:36:22] DEBUG[9864] chan_sip.c: Hangup call SIP/5080-09587fa8, SIP callid 1536432007-839465162063105682@208.51.102.30) [May 31 07:36:22] DEBUG[9864] devicestate.c: Notification of state change to be queued on device/channel SIP/5080-09587fa8 [May 31 07:36:22] DEBUG[2267] devicestate.c: No provider found, checking channel drivers for SIP - 5080 [May 31 07:36:22] DEBUG[2267] chan_sip.c: Checking device state for peer 5080 [May 31 07:36:22] DEBUG[2267] devicestate.c: Changing state for SIP/5080 - state 4 (Invalid) [May 31 07:36:22] DEBUG[2270] chan_sip.c: = Found Their Call ID: 1536432007-839465162063105682@208.51.102.30 Their Tag GR52RWG346-34 Our tag: as41ff4030 [May 31 07:36:22] DEBUG[2270] chan_sip.c: Stopping retransmission on '1536432007-839465162063105682@208.51.102.30' of Request 102: Match Not Found [May 31 07:36:22] VERBOSE[2270] logger.c: [May 31 07:36:22] Really destroying SIP dialog '1536432007-839465162063105682@208.51.102.30' Method: ACK