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