Jun 28 22:27:32 DEBUG[19565]: chan_sip.c:4104 sip_alloc: Allocating new SIP dialog for 00078599-3d3d001c-0d5dc203-48ad7071@192.168.0.200 - INVITE (With RTP) Jun 28 22:27:32 DEBUG[19565]: chan_sip.c:13979 handle_request: **** Received INVITE (5) - Command in SIP INVITE Jun 28 22:27:32 DEBUG[19565]: chan_sip.c:8621 check_user_full: Setting NAT on RTP to Off Jun 28 22:27:32 DEBUG[19565]: chan_sip.c:13979 handle_request: **** Received ACK (6) - Command in SIP ACK Jun 28 22:27:32 DEBUG[19565]: chan_sip.c:1997 __sip_ack: Stopping retransmission on '00078599-3d3d001c-0d5dc203-48ad7071@192.168.0.200' of Response 101: Match Not Found Jun 28 22:27:32 DEBUG[19565]: chan_sip.c:13979 handle_request: **** Received INVITE (5) - Command in SIP INVITE Jun 28 22:27:32 DEBUG[19565]: chan_sip.c:8621 check_user_full: Setting NAT on RTP to Off Jun 28 22:27:32 DEBUG[19565]: chan_sip.c:4834 process_sdp: T38 state changed to 0 on channel Jun 28 22:27:32 DEBUG[19565]: chan_sip.c:4904 process_sdp: We're settling with these formats: 0xe (gsm|ulaw|alaw) Jun 28 22:27:32 DEBUG[19565]: chan_sip.c:12796 handle_request_invite: Checking SIP call limits for device 7706 Jun 28 22:27:32 DEBUG[19565]: chan_sip.c:2864 update_call_counter: Updating call counter for incoming call Jun 28 22:27:32 DEBUG[19565]: chan_sip.c:3599 sip_new: *** Our native formats are 0x4 (ulaw) Jun 28 22:27:32 DEBUG[19565]: chan_sip.c:3600 sip_new: *** Joint capabilities are 0xe (gsm|ulaw|alaw) Jun 28 22:27:32 DEBUG[19565]: chan_sip.c:3601 sip_new: *** Our capabilities are 0xe (gsm|ulaw|alaw) Jun 28 22:27:32 DEBUG[19565]: chan_sip.c:3602 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) Jun 28 22:27:32 DEBUG[19565]: chan_sip.c:3625 sip_new: This channel will not be able to handle video. Jun 28 22:27:32 DEBUG[19565]: chan_sip.c:7584 build_route: build_route: Contact hop: Jun 28 22:27:32 DEBUG[19565]: chan_sip.c:12866 handle_request_invite: SIP/7706-085cbd08: New call is still down.... Trying... Jun 28 22:27:32 DEBUG[19565]: devicestate.c:301 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/7706-085cbd08 Jun 28 22:27:32 DEBUG[19552]: devicestate.c:159 ast_device_state: No provider found, checking channel drivers for SIP - 7706 Jun 28 22:27:32 DEBUG[19552]: chan_sip.c:14548 sip_devicestate: Checking device state for peer 7706 Jun 28 22:27:32 DEBUG[19552]: devicestate.c:285 do_state_change: Changing state for SIP/7706 - state 1 (Not in use) Jun 28 22:27:32 DEBUG[19619]: pbx.c:1675 pbx_extension_helper: Launching 'Answer' -- Executing [7704@from-sip:1] Answer("SIP/7706-085cbd08", "") in new stack Jun 28 22:27:32 DEBUG[19619]: devicestate.c:301 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/7706-085cbd08 Jun 28 22:27:32 DEBUG[19619]: chan_sip.c:3305 sip_answer: SIP answering channel: SIP/7706-085cbd08 Jun 28 22:27:32 DEBUG[19619]: chan_sip.c:5800 add_sdp: ** Our capability: 0xe (gsm|ulaw|alaw) Video flag: True Jun 28 22:27:32 DEBUG[19619]: chan_sip.c:5801 add_sdp: ** Our prefcodec: 0x0 (nothing) Jun 28 22:27:32 DEBUG[19619]: chan_sip.c:5951 add_sdp: -- Done with adding codecs to SDP Jun 28 22:27:32 DEBUG[19619]: chan_sip.c:5990 add_sdp: Done building SDP. Settling with this capability: 0xe (gsm|ulaw|alaw) Jun 28 22:27:32 DEBUG[19619]: pbx.c:1675 pbx_extension_helper: Launching 'MixMonitor' -- Executing [7704@from-sip:2] MixMonitor("SIP/7706-085cbd08", "1151530052.2.gsm") in new stack Jun 28 22:27:32 DEBUG[19552]: devicestate.c:159 ast_device_state: No provider found, checking channel drivers for SIP - 7706 Jun 28 22:27:32 DEBUG[19552]: chan_sip.c:14548 sip_devicestate: Checking device state for peer 7706 Jun 28 22:27:32 DEBUG[19552]: devicestate.c:285 do_state_change: Changing state for SIP/7706 - state 1 (Not in use) Jun 28 22:27:32 DEBUG[19620]: app_queue.c:529 changethread: Device 'SIP/7706' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. Jun 28 22:27:32 DEBUG[19621]: app_queue.c:529 changethread: Device 'SIP/7706' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. Jun 28 22:27:32 DEBUG[19619]: channel.c:1164 ast_channel_spy_add: Spy MixMonitor added to channel SIP/7706-085cbd08 Jun 28 22:27:32 DEBUG[19619]: pbx.c:1675 pbx_extension_helper: Launching 'SayDigits' -- Executing [7704@from-sip:3] SayDigits("SIP/7706-085cbd08", "123456") in new stack Jun 28 22:27:32 DEBUG[19619]: channel.c:2484 set_format: Set channel SIP/7706-085cbd08 to write format ulaw Jun 28 22:27:32 DEBUG[19619]: channel.c:1318 queue_frame_to_spies: Building translator from ulaw to SLINEAR for spies on channel SIP/7706-085cbd08 Jun 28 22:27:32 DEBUG[19619]: rtp.c:2341 ast_rtp_write: Ooh, format changed from unknown to ulaw Jun 28 22:27:32 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 160 sample intervals -- Playing 'digits/1' (language 'en') == Begin MixMonitor Recording SIP/7706-085cbd08 Jun 28 22:27:33 DEBUG[19619]: channel.c:1318 queue_frame_to_spies: Building translator from ulaw to SLINEAR for spies on channel SIP/7706-085cbd08 Jun 28 22:27:33 DEBUG[19565]: chan_sip.c:13979 handle_request: **** Received ACK (6) - Command in SIP ACK Jun 28 22:27:33 DEBUG[19565]: chan_sip.c:1997 __sip_ack: Stopping retransmission on '00078599-3d3d001c-0d5dc203-48ad7071@192.168.0.200' of Response 102: Match Not Found Jun 28 22:27:33 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 134 sample intervals Jun 28 22:27:33 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 0 sample intervals Jun 28 22:27:33 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 0 sample intervals Jun 28 22:27:33 DEBUG[19619]: channel.c:2484 set_format: Set channel SIP/7706-085cbd08 to write format ulaw Jun 28 22:27:33 DEBUG[19619]: channel.c:2484 set_format: Set channel SIP/7706-085cbd08 to write format ulaw Jun 28 22:27:33 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 160 sample intervals -- Playing 'digits/2' (language 'en') Jun 28 22:27:33 DEBUG[19619]: channel.c:1367 queue_frame_to_spies: Switching spy 'MixMonitor' on 'SIP/7706-085cbd08' to write-trigger mode Jun 28 22:27:33 DEBUG[19619]: channel.c:1382 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'SIP/7706-085cbd08' Jun 28 22:27:34 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 120 sample intervals Jun 28 22:27:34 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 0 sample intervals Jun 28 22:27:34 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 0 sample intervals Jun 28 22:27:34 DEBUG[19619]: channel.c:2484 set_format: Set channel SIP/7706-085cbd08 to write format ulaw Jun 28 22:27:34 DEBUG[19619]: channel.c:2484 set_format: Set channel SIP/7706-085cbd08 to write format ulaw Jun 28 22:27:34 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 160 sample intervals -- Playing 'digits/3' (language 'en') Jun 28 22:27:35 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 0 sample intervals Jun 28 22:27:35 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 0 sample intervals Jun 28 22:27:35 DEBUG[19619]: channel.c:2484 set_format: Set channel SIP/7706-085cbd08 to write format ulaw Jun 28 22:27:35 DEBUG[19619]: channel.c:2484 set_format: Set channel SIP/7706-085cbd08 to write format ulaw Jun 28 22:27:35 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 160 sample intervals -- Playing 'digits/4' (language 'en') Jun 28 22:27:35 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 147 sample intervals Jun 28 22:27:35 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 0 sample intervals Jun 28 22:27:35 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 0 sample intervals Jun 28 22:27:35 DEBUG[19619]: channel.c:2484 set_format: Set channel SIP/7706-085cbd08 to write format ulaw Jun 28 22:27:35 DEBUG[19619]: channel.c:2484 set_format: Set channel SIP/7706-085cbd08 to write format ulaw Jun 28 22:27:35 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 160 sample intervals -- Playing 'digits/5' (language 'en') Jun 28 22:27:36 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 0 sample intervals Jun 28 22:27:36 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 0 sample intervals Jun 28 22:27:36 DEBUG[19619]: channel.c:2484 set_format: Set channel SIP/7706-085cbd08 to write format ulaw Jun 28 22:27:36 DEBUG[19619]: channel.c:2484 set_format: Set channel SIP/7706-085cbd08 to write format ulaw Jun 28 22:27:36 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 160 sample intervals -- Playing 'digits/6' (language 'en') Jun 28 22:27:37 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 54 sample intervals Jun 28 22:27:37 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 0 sample intervals Jun 28 22:27:37 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 0 sample intervals Jun 28 22:27:37 DEBUG[19619]: channel.c:2484 set_format: Set channel SIP/7706-085cbd08 to write format ulaw Jun 28 22:27:37 DEBUG[19619]: pbx.c:1675 pbx_extension_helper: Launching 'VoiceMail' -- Executing [7704@from-sip:4] VoiceMail("SIP/7706-085cbd08", "780|su") in new stack Jun 28 22:27:37 DEBUG[19619]: app_voicemail.c:2502 leave_voicemail: /var/spool/asterisk/voicemail/default/780/unavail doesn't exist, doing what we can Jun 28 22:27:37 DEBUG[19619]: channel.c:2484 set_format: Set channel SIP/7706-085cbd08 to write format ulaw Jun 28 22:27:37 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 160 sample intervals -- Playing 'vm-theperson' (language 'en') Jun 28 22:27:38 DEBUG[19565]: chan_sip.c:1926 __sip_autodestruct: Auto destroying call '0003e3a5-22690002-23a48236-2ec5d118@90.0.0.149' Jun 28 22:27:38 DEBUG[19565]: chan_sip.c:2970 sip_destroy: Destroying SIP dialog 0003e3a5-22690002-23a48236-2ec5d118@90.0.0.149 Really destroying SIP dialog '0003e3a5-22690002-23a48236-2ec5d118@90.0.0.149' Method: REGISTER Jun 28 22:27:38 DEBUG[19565]: chan_sip.c:1926 __sip_autodestruct: Auto destroying call '000ccebd-cfc60002-23a5019f-3b502eb3@192.168.6.215' Jun 28 22:27:38 DEBUG[19565]: chan_sip.c:2970 sip_destroy: Destroying SIP dialog 000ccebd-cfc60002-23a5019f-3b502eb3@192.168.6.215 Really destroying SIP dialog '000ccebd-cfc60002-23a5019f-3b502eb3@192.168.6.215' Method: REGISTER Jun 28 22:27:39 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 120 sample intervals Jun 28 22:27:39 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 0 sample intervals Jun 28 22:27:39 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 0 sample intervals Jun 28 22:27:39 DEBUG[19619]: channel.c:2484 set_format: Set channel SIP/7706-085cbd08 to write format ulaw Jun 28 22:27:39 DEBUG[19619]: channel.c:2484 set_format: Set channel SIP/7706-085cbd08 to write format ulaw Jun 28 22:27:39 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 160 sample intervals -- Playing 'digits/7' (language 'en') Jun 28 22:27:40 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 27 sample intervals Jun 28 22:27:40 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 0 sample intervals Jun 28 22:27:40 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 0 sample intervals Jun 28 22:27:40 DEBUG[19619]: channel.c:2484 set_format: Set channel SIP/7706-085cbd08 to write format ulaw Jun 28 22:27:40 DEBUG[19619]: channel.c:2484 set_format: Set channel SIP/7706-085cbd08 to write format ulaw Jun 28 22:27:40 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 160 sample intervals -- Playing 'digits/8' (language 'en') Jun 28 22:27:40 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 107 sample intervals Jun 28 22:27:40 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 0 sample intervals Jun 28 22:27:40 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 0 sample intervals Jun 28 22:27:40 DEBUG[19619]: channel.c:2484 set_format: Set channel SIP/7706-085cbd08 to write format ulaw Jun 28 22:27:40 DEBUG[19619]: channel.c:2484 set_format: Set channel SIP/7706-085cbd08 to write format ulaw Jun 28 22:27:40 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 160 sample intervals -- Playing 'digits/0' (language 'en') Jun 28 22:27:41 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 54 sample intervals Jun 28 22:27:41 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 0 sample intervals Jun 28 22:27:41 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 0 sample intervals Jun 28 22:27:41 DEBUG[19619]: channel.c:2484 set_format: Set channel SIP/7706-085cbd08 to write format ulaw Jun 28 22:27:41 DEBUG[19619]: channel.c:2484 set_format: Set channel SIP/7706-085cbd08 to write format ulaw Jun 28 22:27:41 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 160 sample intervals -- Playing 'vm-isunavail' (language 'en') Jun 28 22:27:42 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 40 sample intervals Jun 28 22:27:42 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 0 sample intervals Jun 28 22:27:42 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 0 sample intervals Jun 28 22:27:42 DEBUG[19619]: channel.c:2484 set_format: Set channel SIP/7706-085cbd08 to write format ulaw Jun 28 22:27:42 DEBUG[19619]: app.c:942 ast_lock_path: Locked path '/var/spool/asterisk/voicemail/default/780/INBOX' Jun 28 22:27:42 DEBUG[19619]: app.c:953 ast_unlock_path: Unlocked path '/var/spool/asterisk/voicemail/default/780/INBOX' Jun 28 22:27:42 DEBUG[19619]: channel.c:2484 set_format: Set channel SIP/7706-085cbd08 to write format gsm Jun 28 22:27:42 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 160 sample intervals -- Playing 'beep' (language 'en') Jun 28 22:27:43 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 0 sample intervals Jun 28 22:27:43 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 0 sample intervals Jun 28 22:27:43 DEBUG[19619]: channel.c:2484 set_format: Set channel SIP/7706-085cbd08 to write format ulaw -- Recording the message Jun 28 22:27:43 DEBUG[19619]: app.c:520 __ast_play_and_record: play_and_record: , /var/spool/asterisk/voicemail/default/780/tmp/NRijR0, 'gsm' Jun 28 22:27:43 DEBUG[19619]: app.c:541 __ast_play_and_record: Recording Formats: sfmts=gsm -- x=0, open writing: /var/spool/asterisk/voicemail/default/780/tmp/NRijR0 format: gsm, 0x8596070 Jun 28 22:27:43 DEBUG[19619]: channel.c:2484 set_format: Set channel SIP/7706-085cbd08 to read format slin Jun 28 22:27:43 DEBUG[19619]: rtp.c:641 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) Jun 28 22:27:43 DEBUG[19619]: rtp.c:641 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) Jun 28 22:27:43 DEBUG[19619]: rtp.c:641 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) Jun 28 22:27:43 DEBUG[19619]: rtp.c:641 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) Jun 28 22:27:43 DEBUG[19619]: rtp.c:641 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) Jun 28 22:27:43 DEBUG[19619]: channel.c:1376 queue_frame_to_spies: Switching spy 'MixMonitor' on 'SIP/7706-085cbd08' to read-trigger mode Jun 28 22:27:43 DEBUG[19619]: channel.c:1382 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'SIP/7706-085cbd08' Jun 28 22:27:43 DEBUG[19619]: rtp.c:641 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) Jun 28 22:27:43 DEBUG[19619]: rtp.c:641 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) Jun 28 22:27:43 DEBUG[19619]: rtp.c:541 send_dtmf: Sending dtmf: 35 (#), at 192.168.0.200 -- User ended message by pressing # Jun 28 22:27:43 DEBUG[19619]: channel.c:2484 set_format: Set channel SIP/7706-085cbd08 to read format ulaw Jun 28 22:27:43 DEBUG[19619]: channel.c:2484 set_format: Set channel SIP/7706-085cbd08 to write format ulaw Jun 28 22:27:43 DEBUG[19619]: rtp.c:2240 ast_rtp_raw_write: Difference is 2560, ms is 340 Jun 28 22:27:43 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 160 sample intervals -- Playing 'auth-thankyou' (language 'en') Jun 28 22:27:43 DEBUG[19619]: rtp.c:641 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) Jun 28 22:27:43 DEBUG[19619]: rtp.c:641 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) Jun 28 22:27:45 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 67 sample intervals Jun 28 22:27:45 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 0 sample intervals Jun 28 22:27:45 DEBUG[19619]: channel.c:1785 ast_settimeout: Scheduling timer at 0 sample intervals Jun 28 22:27:45 DEBUG[19619]: channel.c:2484 set_format: Set channel SIP/7706-085cbd08 to write format ulaw Jun 28 22:27:45 DEBUG[19619]: app.c:942 ast_lock_path: Locked path '/var/spool/asterisk/voicemail/default/780/INBOX' Jun 28 22:27:45 DEBUG[19619]: app.c:953 ast_unlock_path: Unlocked path '/var/spool/asterisk/voicemail/default/780/INBOX' Jun 28 22:27:45 DEBUG[19619]: app_voicemail.c:1766 sendmail: Attaching file '/var/spool/asterisk/voicemail/default/780/INBOX/msg0036', format 'gsm', uservm is '2048', global is 2048 Jun 28 22:27:45 DEBUG[19619]: app_voicemail.c:1882 sendmail: Sent mail to jmls@tessera.co.uk with command '/usr/sbin/sendmail -t' Jun 28 22:27:45 DEBUG[19619]: app_voicemail.c:1965 sendpage: Sent page to attach=no with command '/usr/sbin/sendmail -t' Jun 28 22:27:45 DEBUG[19619]: pbx.c:1675 pbx_extension_helper: Launching 'Hangup' -- Executing [7704@from-sip:5] Hangup("SIP/7706-085cbd08", "") in new stack Jun 28 22:27:45 DEBUG[19619]: pbx.c:2258 __ast_pbx_run: Spawn extension (from-sip,7704,5) exited non-zero on 'SIP/7706-085cbd08' Jun 28 22:27:45 DEBUG[19619]: pbx.c:1675 pbx_extension_helper: Launching 'NoOp' -- Executing [h@from-sip:1] NoOp("SIP/7706-085cbd08", "Reached Hangup Extension") in new stack Jun 28 22:27:45 DEBUG[19619]: pbx.c:1675 pbx_extension_helper: Launching 'Hangup' -- Executing [h@from-sip:2] Hangup("SIP/7706-085cbd08", "") in new stack Jun 28 22:27:45 DEBUG[19619]: pbx.c:2378 __ast_pbx_run: Spawn extension (from-sip,h,2) exited non-zero on 'SIP/7706-085cbd08' == End MixMonitor Recording SIP/7706-085cbd08 *** glibc detected *** malloc(): memory corruption: 0x08596490 *** Aborted (core dumped) You have new mail in /var/spool/mail/root [root@foxtrot tmp]#