[Nov 7 18:50:36] DEBUG[25482]: chan_sip.c:9123 find_call: = Looking for Call ID: 0001A4A0-DC86-1273-8749-2230B00AAA77-325543@10.176.48.36 (Checking From) --From tag 0001A4DC-DC86-1273-8749-2230B00AAA77-325866 --To-tag as4ab62a79 [Nov 7 18:50:36] DEBUG[25482][C-0000083a]: logger.c:1324 ast_callid_threadassoc_add: CALL_ID [C-0000083a] bound to thread. [Nov 7 18:50:36] DEBUG[25482][C-0000083a]: chan_sip.c:27891 handle_incoming: **** Received ACK (6) - Command in SIP ACK [Nov 7 18:50:36] DEBUG[25482][C-0000083a]: chan_sip.c:4561 __sip_ack: Stopping retransmission on '0001A4A0-DC86-1273-8749-2230B00AAA77-325543@10.176.48.36' of Response 1: Match Found [Nov 7 18:50:36] DEBUG[25482][C-0000083a]: logger.c:1346 ast_callid_threadassoc_remove: Call_ID [C-0000083a] being removed from thread. [Nov 7 18:50:36] DEBUG[15336][C-0000083a]: res_rtp_asterisk.c:3503 ast_rtp_read: 0x7f6c78022a10 -- Probation learning mode pass with source address 10.104.200.33:53576 > 0x7f6c78022a10 -- Probation passed - setting RTP source address to 10.104.200.33:53576 [Nov 7 18:50:36] DEBUG[15336][C-0000083a]: app_voicemail.c:6284 leave_voicemail: Before find_user [Nov 7 18:50:36] DEBUG[15336][C-0000083a]: res_config_odbc.c:87 custom_prepare: Skip: 0; SQL: SELECT * FROM DYN_VM_USERS WHERE mailbox = ? AND context = ? [Nov 7 18:50:36] DEBUG[15336][C-0000083a]: res_config_odbc.c:103 custom_prepare: Parameter 1 ('mailbox') = '2344003006' [Nov 7 18:50:36] DEBUG[15336][C-0000083a]: res_config_odbc.c:103 custom_prepare: Parameter 2 ('context') = 'GVMA_DN' [Nov 7 18:50:36] DEBUG[15336][C-0000083a]: res_odbc.c:1053 odbc_release_obj2: odbc_release_obj2(0x7f6c480ee368) called (obj->txf = (nil)) [Nov 7 18:50:36] DEBUG[15336][C-0000083a]: res_odbc.c:1053 odbc_release_obj2: odbc_release_obj2(0x7f6c480ee368) called (obj->txf = (nil)) [Nov 7 18:50:36] DEBUG[15336][C-0000083a]: res_odbc.c:1053 odbc_release_obj2: odbc_release_obj2(0x7f6c480ee368) called (obj->txf = (nil)) [Nov 7 18:50:36] DEBUG[15336][C-0000083a]: channel.c:5359 set_format: Set channel SIP/Asterisk_CLE-00000836 to write format slin [Nov 7 18:50:36] DEBUG[15336][C-0000083a]: res_rtp_asterisk.c:2631 ast_rtp_write: Ooh, format changed from unknown to ulaw [Nov 7 18:50:36] DEBUG[15336][C-0000083a]: res_rtp_asterisk.c:2666 ast_rtp_write: Created smoother: format: ulaw ms: 20 len: 160 [Nov 7 18:50:36] DEBUG[15336][C-0000083a]: channel.c:3575 ast_settimeout: Scheduling timer at (50 requested / 50 actual) timer ticks per second -- Playing '/var/spool/asterisk/voicemail/GVMA_DN/2344003006/unavail.slin' (language 'en') [Nov 7 18:50:40] DEBUG[25482]: chan_sip.c:9123 find_call: = Looking for Call ID: 006E415A-DC57-1273-B36F-22A3680AAA77-325987@10.104.163.36 (Checking From) --From tag 006E4178-DC57-1273-B36F-22A3680AAA77-338522 --To-tag [Nov 7 18:50:40] DEBUG[25482]: acl.c:979 ast_ouraddrfor: For destination '10.104.163.36', our source address is '10.104.163.5'. [Nov 7 18:50:40] DEBUG[25482]: chan_sip.c:4026 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 10.104.163.5:5060 [Nov 7 18:50:40] DEBUG[25482]: chan_sip.c:8726 sip_alloc: Allocating new SIP dialog for 006E415A-DC57-1273-B36F-22A3680AAA77-325987@10.104.163.36 - OPTIONS (No RTP) [Nov 7 18:50:40] DEBUG[25482]: chan_sip.c:27891 handle_incoming: **** Received OPTIONS (3) - Command in SIP OPTIONS [Nov 7 18:50:40] DEBUG[25482]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '10.104.163.5:5060' into... [Nov 7 18:50:40] DEBUG[25482]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '10.104.163.5' and port ''. [Nov 7 18:50:40] DEBUG[25482]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '10.104.163.36:5060' into... [Nov 7 18:50:40] DEBUG[25482]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '10.104.163.36' and port ''. [Nov 7 18:50:40] DEBUG[25482]: chan_sip.c:3869 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.104.163.36:5060 [Nov 7 18:50:42] DEBUG[25482]: chan_sip.c:4417 __sip_autodestruct: Auto destroying SIP dialog '006E415A-DC57-1273-B36F-22A3680AAA77-325970@10.104.163.36' [Nov 7 18:50:42] DEBUG[25482]: chan_sip.c:6822 sip_destroy: Destroying SIP dialog 006E415A-DC57-1273-B36F-22A3680AAA77-325970@10.104.163.36 [Nov 7 18:50:42] DEBUG[15336][C-0000083a]: channel.c:3575 ast_settimeout: Scheduling timer at (58 requested / 58 actual) timer ticks per second [Nov 7 18:50:42] DEBUG[15336][C-0000083a]: channel.c:3575 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Nov 7 18:50:42] DEBUG[15336][C-0000083a]: channel.c:3575 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Nov 7 18:50:42] DEBUG[15336][C-0000083a]: channel.c:3575 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Nov 7 18:50:42] DEBUG[15336][C-0000083a]: channel.c:5359 set_format: Set channel SIP/Asterisk_CLE-00000836 to write format ulaw [Nov 7 18:50:42] DEBUG[15336][C-0000083a]: channel.c:3575 ast_settimeout: Scheduling timer at (50 requested / 50 actual) timer ticks per second -- Playing 'vm-intro.ulaw' (language 'en') [Nov 7 18:50:47] DEBUG[25482]: chan_sip.c:9123 find_call: = Looking for Call ID: 0001A4A0-DC86-1273-8749-2230B00AAA77-325549@10.176.48.36 (Checking From) --From tag 0001A4DC-DC86-1273-8749-2230B00AAA77-325872 --To-tag [Nov 7 18:50:47] DEBUG[25482]: acl.c:979 ast_ouraddrfor: For destination '10.176.48.36', our source address is '10.104.163.5'. [Nov 7 18:50:47] DEBUG[25482]: chan_sip.c:4026 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 10.104.163.5:5060 [Nov 7 18:50:47] DEBUG[25482]: chan_sip.c:8726 sip_alloc: Allocating new SIP dialog for 0001A4A0-DC86-1273-8749-2230B00AAA77-325549@10.176.48.36 - OPTIONS (No RTP) [Nov 7 18:50:47] DEBUG[25482]: chan_sip.c:27891 handle_incoming: **** Received OPTIONS (3) - Command in SIP OPTIONS [Nov 7 18:50:47] DEBUG[25482]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '10.176.48.5:5060' into... [Nov 7 18:50:47] DEBUG[25482]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '10.176.48.5' and port ''. [Nov 7 18:50:47] DEBUG[25482]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '10.176.48.36:5060' into... [Nov 7 18:50:47] DEBUG[25482]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '10.176.48.36' and port ''. [Nov 7 18:50:47] DEBUG[25482]: chan_sip.c:3869 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.176.48.36:5060 [Nov 7 18:50:48] DEBUG[15336][C-0000083a]: channel.c:3575 ast_settimeout: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Nov 7 18:50:48] DEBUG[15336][C-0000083a]: channel.c:3575 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Nov 7 18:50:48] DEBUG[15336][C-0000083a]: channel.c:3575 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Nov 7 18:50:48] DEBUG[15336][C-0000083a]: channel.c:3575 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Nov 7 18:50:48] DEBUG[15336][C-0000083a]: res_odbc.c:1053 odbc_release_obj2: odbc_release_obj2(0x7f6c480ee368) called (obj->txf = (nil)) [Nov 7 18:50:48] DEBUG[15336][C-0000083a]: channel.c:3575 ast_settimeout: Scheduling timer at (50 requested / 50 actual) timer ticks per second -- Playing 'beep.ulaw' (language 'en') [Nov 7 18:50:48] DEBUG[15336][C-0000083a]: channel.c:3575 ast_settimeout: Scheduling timer at (182 requested / 182 actual) timer ticks per second [Nov 7 18:50:48] DEBUG[15336][C-0000083a]: channel.c:3575 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Nov 7 18:50:48] DEBUG[15336][C-0000083a]: channel.c:3575 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Nov 7 18:50:48] DEBUG[15336][C-0000083a]: channel.c:3575 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second -- Recording the message [Nov 7 18:50:48] DEBUG[15336][C-0000083a]: app.c:1159 __ast_play_and_record: play_and_record: , /var/spool/asterisk/voicemail/GVMA_DN/2344003006/tmp/2cRIY0, 'wav' [Nov 7 18:50:48] DEBUG[15336][C-0000083a]: app.c:1183 __ast_play_and_record: Recording Formats: sfmts=wav -- x=0, open writing: /var/spool/asterisk/voicemail/GVMA_DN/2344003006/tmp/2cRIY0 format: wav, 0x7f6c58006018 [Nov 7 18:50:48] DEBUG[15336][C-0000083a]: dsp.c:482 ast_tone_detect_init: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Nov 7 18:50:48] DEBUG[15336][C-0000083a]: dsp.c:482 ast_tone_detect_init: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Nov 7 18:50:48] DEBUG[15336][C-0000083a]: channel.c:5359 set_format: Set channel SIP/Asterisk_CLE-00000836 to read format slin [Nov 7 18:50:48] DEBUG[25482]: chan_sip.c:4417 __sip_autodestruct: Auto destroying SIP dialog '0001A4A0-DC86-1273-8749-2230B00AAA77-325529@10.176.48.36' [Nov 7 18:50:48] DEBUG[25482]: chan_sip.c:6822 sip_destroy: Destroying SIP dialog 0001A4A0-DC86-1273-8749-2230B00AAA77-325529@10.176.48.36 [Nov 7 18:50:52] DEBUG[25482]: chan_sip.c:9123 find_call: = Looking for Call ID: 0001A4A0-DC86-1273-8749-2230B00AAA77-325543@10.176.48.36 (Checking From) --From tag 0001A4DC-DC86-1273-8749-2230B00AAA77-325866 --To-tag as4ab62a79 [Nov 7 18:50:52] DEBUG[25482][C-0000083a]: logger.c:1324 ast_callid_threadassoc_add: CALL_ID [C-0000083a] bound to thread. [Nov 7 18:50:52] DEBUG[25482][C-0000083a]: chan_sip.c:27891 handle_incoming: **** Received BYE (8) - Command in SIP BYE [Nov 7 18:50:52] DEBUG[25482][C-0000083a]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '10.176.48.36:5060' into... [Nov 7 18:50:52] DEBUG[25482][C-0000083a]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '10.176.48.36' and port '5060'. [Nov 7 18:50:52] DEBUG[25482][C-0000083a]: chan_sip.c:3525 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 0001A4A0-DC86-1273-8749-2230B00AAA77-325543@10.176.48.36 [Nov 7 18:50:52] DEBUG[25482][C-0000083a]: res_rtp_asterisk.c:3906 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f6c780dd9a8' [Nov 7 18:50:52] DEBUG[25482][C-0000083a]: chan_sip.c:28808 stop_session_timer: Session timer stopped: 136797 - 0001A4A0-DC86-1273-8749-2230B00AAA77-325543@10.176.48.36 [Nov 7 18:50:52] DEBUG[25482][C-0000083a]: chan_sip.c:26528 handle_request_bye: Received bye, issuing owner hangup [Nov 7 18:50:52] DEBUG[25482][C-0000083a]: chan_sip.c:3869 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.176.48.36:5060 [Nov 7 18:50:52] DEBUG[25482][C-0000083a]: logger.c:1346 ast_callid_threadassoc_remove: Call_ID [C-0000083a] being removed from thread. -- User hung up [Nov 7 18:50:52] DEBUG[15336][C-0000083a]: channel.c:5359 set_format: Set channel SIP/Asterisk_CLE-00000836 to read format ulaw [Nov 7 18:50:52] DEBUG[15336][C-0000083a]: app.c:1746 ast_lock_path_lockfile: Locked path '/var/spool/asterisk/voicemail/GVMA_DN/2344003006/INBOX' [Nov 7 18:50:52] DEBUG[15336][C-0000083a]: res_odbc.c:1053 odbc_release_obj2: odbc_release_obj2(0x7f6c480ee368) called (obj->txf = (nil)) [Nov 7 18:50:52] DEBUG[15336][C-0000083a]: app.c:1763 ast_unlock_path_lockfile: Unlocked path '/var/spool/asterisk/voicemail/GVMA_DN/2344003006/INBOX' [Nov 7 18:50:52] DEBUG[15336][C-0000083a]: res_odbc.c:1053 odbc_release_obj2: odbc_release_obj2(0x7f6c480ee368) called (obj->txf = (nil)) [Nov 7 18:50:52] DEBUG[15336][C-0000083a]: config.c:1644 config_text_file_load: Parsing /var/spool/asterisk/voicemail/GVMA_DN/2344003006/INBOX/msg0001.txt == Parsing '/var/spool/asterisk/voicemail/GVMA_DN/2344003006/INBOX/msg0001.txt': Found [Nov 7 18:50:52] DEBUG[15336][C-0000083a]: res_odbc.c:1053 odbc_release_obj2: odbc_release_obj2(0x7f6c480ee368) called (obj->txf = (nil)) [Nov 7 18:50:52] DEBUG[15336][C-0000083a]: app_voicemail.c:5193 sendmail: Attaching file '/var/spool/asterisk/voicemail/GVMA_DN/2344003006/INBOX/msg0001', format 'wav', uservm is '0', global is 0 [Nov 7 18:50:52] DEBUG[15336][C-0000083a]: config.c:1644 config_text_file_load: Parsing /var/spool/asterisk/voicemail/GVMA_DN/2344003006/INBOX/msg0001.txt == Parsing '/var/spool/asterisk/voicemail/GVMA_DN/2344003006/INBOX/msg0001.txt': Found [Nov 7 18:50:52] DEBUG[15336][C-0000083a]: config.c:1644 config_text_file_load: Parsing /var/spool/asterisk/voicemail/GVMA_DN/2344003006/INBOX/msg0001.txt == Parsing '/var/spool/asterisk/voicemail/GVMA_DN/2344003006/INBOX/msg0001.txt': Found [Nov 7 18:50:52] DEBUG[15336][C-0000083a]: pbx.c:4228 ast_str_substitute_variables_full: Evaluating 'VM_MSGNUM' (from 'VM_MSGNUM} in mailbox ${VM_MAILBOX}' len 9) [Nov 7 18:50:52] DEBUG[15336][C-0000083a]: pbx.c:3642 ast_str_retrieve_variable: Result of 'VM_MSGNUM' is '2' [Nov 7 18:50:52] DEBUG[15336][C-0000083a]: pbx.c:4228 ast_str_substitute_variables_full: Evaluating 'VM_MAILBOX' (from 'VM_MAILBOX}' len 10) [Nov 7 18:50:52] DEBUG[15336][C-0000083a]: pbx.c:3642 ast_str_retrieve_variable: Result of 'VM_MAILBOX' is '2344003006' [Nov 7 18:50:52] DEBUG[15336][C-0000083a]: config.c:1644 config_text_file_load: Parsing /var/spool/asterisk/voicemail/GVMA_DN/2344003006/INBOX/msg0001.txt == Parsing '/var/spool/asterisk/voicemail/GVMA_DN/2344003006/INBOX/msg0001.txt': Found [Nov 7 18:50:52] DEBUG[15336][C-0000083a]: pbx.c:4228 ast_str_substitute_variables_full: Evaluating 'VM_NAME' (from 'VM_NAME}, You have ${VM_MSGNUM} message(s) in mailbox ${VM_Mailbox}. New Message from phone number ${VM_CALLERID} with a duration of ${VM_DUR} on ${VM_DATE}.' len 7) [Nov 7 18:50:52] DEBUG[15336][C-0000083a]: pbx.c:3642 ast_str_retrieve_variable: Result of 'VM_NAME' is 'Kevin Shumway' [Nov 7 18:50:52] DEBUG[15336][C-0000083a]: pbx.c:4228 ast_str_substitute_variables_full: Evaluating 'VM_MSGNUM' (from 'VM_MSGNUM} message(s) in mailbox ${VM_Mailbox}. New Message from phone number ${VM_CALLERID} with a duration of ${VM_DUR} on ${VM_DATE}.' len 9) [Nov 7 18:50:52] DEBUG[15336][C-0000083a]: pbx.c:3642 ast_str_retrieve_variable: Result of 'VM_MSGNUM' is '2' [Nov 7 18:50:52] DEBUG[15336][C-0000083a]: pbx.c:4228 ast_str_substitute_variables_full: Evaluating 'VM_Mailbox' (from 'VM_Mailbox}. New Message from phone number ${VM_CALLERID} with a duration of ${VM_DUR} on ${VM_DATE}.' len 10) [Nov 7 18:50:52] DEBUG[15336][C-0000083a]: pbx.c:3642 ast_str_retrieve_variable: Result of 'VM_Mailbox' is '2344003006' [Nov 7 18:50:52] DEBUG[15336][C-0000083a]: pbx.c:4228 ast_str_substitute_variables_full: Evaluating 'VM_CALLERID' (from 'VM_CALLERID} with a duration of ${VM_DUR} on ${VM_DATE}.' len 11) [Nov 7 18:50:52] DEBUG[15336][C-0000083a]: pbx.c:3642 ast_str_retrieve_variable: Result of 'VM_CALLERID' is '"WIRELESS CALLER" <4802319830>' [Nov 7 18:50:52] DEBUG[15336][C-0000083a]: pbx.c:4228 ast_str_substitute_variables_full: Evaluating 'VM_DUR' (from 'VM_DUR} on ${VM_DATE}.' len 6) [Nov 7 18:50:52] DEBUG[15336][C-0000083a]: pbx.c:3642 ast_str_retrieve_variable: Result of 'VM_DUR' is '0:00' [Nov 7 18:50:52] DEBUG[15336][C-0000083a]: pbx.c:4228 ast_str_substitute_variables_full: Evaluating 'VM_DATE' (from 'VM_DATE}.' len 7) [Nov 7 18:50:52] DEBUG[15336][C-0000083a]: pbx.c:3642 ast_str_retrieve_variable: Result of 'VM_DATE' is 'Thursday, November 07, 2013 at 04:50:52 PM' [Nov 7 18:50:52] DEBUG[15336][C-0000083a]: app_voicemail.c:5204 sendmail: Sent mail to Kevin.Shumway@schwab.com with command '/usr/sbin/sendmail -t' [Nov 7 18:50:52] DEBUG[15336][C-0000083a]: res_odbc.c:1053 odbc_release_obj2: odbc_release_obj2(0x7f6c480ee368) called (obj->txf = (nil)) [Nov 7 18:50:52] DEBUG[15336][C-0000083a]: res_odbc.c:1053 odbc_release_obj2: odbc_release_obj2(0x7f6c480ee368) called (obj->txf = (nil)) [Nov 7 18:50:52] DEBUG[25468]: chan_sip.c:8726 sip_alloc: Allocating new SIP dialog for 4ab84177397eb5d54bf7504c23e450b9@10.104.163.5:5060 - NOTIFY (No RTP) [Nov 7 18:50:52] DEBUG[25468]: acl.c:979 ast_ouraddrfor: For destination '0.0.0.0', our source address is '127.0.0.1'. [Nov 7 18:50:52] DEBUG[25468]: chan_sip.c:4026 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 127.0.0.1:5060 [Nov 7 18:50:52] DEBUG[25468]: chan_sip.c:3512 initialize_initreq: Initializing initreq for method NOTIFY - callid 650572e4432bb6ff08e569b50f19e429@127.0.0.1:5060 [Nov 7 18:50:52] DEBUG[25468]: chan_sip.c:3869 __sip_xmit: Trying to put 'NOTIFY sip:' onto UDP socket destined for 0.0.0.0:5060 [Nov 7 18:50:52] DEBUG[25482]: chan_sip.c:9123 find_call: = Looking for Call ID: 650572e4432bb6ff08e569b50f19e429@127.0.0.1:5060 (Checking From) --From tag as138134da --To-tag [Nov 7 18:50:52] DEBUG[25482]: acl.c:979 ast_ouraddrfor: For destination '127.0.0.1', our source address is '127.0.0.1'. [Nov 7 18:50:52] DEBUG[25482]: chan_sip.c:4026 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 127.0.0.1:5060 [Nov 7 18:50:52] DEBUG[25482]: chan_sip.c:8726 sip_alloc: Allocating new SIP dialog for 650572e4432bb6ff08e569b50f19e429@127.0.0.1:5060 - NOTIFY (No RTP) [Nov 7 18:50:52] DEBUG[25482]: chan_sip.c:27891 handle_incoming: **** Received NOTIFY (4) - Command in SIP NOTIFY [Nov 7 18:50:52] DEBUG[15336][C-0000083a]: res_odbc.c:1053 odbc_release_obj2: odbc_release_obj2(0x7f6c480ee368) called (obj->txf = (nil)) [Nov 7 18:50:52] DEBUG[25482]: res_config_odbc.c:87 custom_prepare: Skip: 0; SQL: SELECT * FROM DYN_SIP_PEERS WHERE host = ? AND port = ? [Nov 7 18:50:52] DEBUG[25482]: res_config_odbc.c:103 custom_prepare: Parameter 1 ('host') = '127.0.0.1' [Nov 7 18:50:52] DEBUG[25482]: res_config_odbc.c:103 custom_prepare: Parameter 2 ('port') = '5060' [Nov 7 18:50:52] DEBUG[25482]: res_odbc.c:1053 odbc_release_obj2: odbc_release_obj2(0x7f6c480ee368) called (obj->txf = (nil)) [Nov 7 18:50:52] DEBUG[15336][C-0000083a]: pbx.c:6316 __ast_pbx_run: Spawn extension (sip,2344003006,12) exited non-zero on 'SIP/Asterisk_CLE-00000836' == Spawn extension (sip, 2344003006, 12) exited non-zero on 'SIP/Asterisk_CLE-00000836' [Nov 7 18:50:52] DEBUG[15336][C-0000083a]: channel.c:2659 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/Asterisk_CLE-00000836' [Nov 7 18:50:52] DEBUG[15336][C-0000083a]: channel.c:2838 ast_hangup: Hanging up channel 'SIP/Asterisk_CLE-00000836' [Nov 7 18:50:52] DEBUG[15336][C-0000083a]: chan_sip.c:7054 sip_hangup: Hangup call SIP/Asterisk_CLE-00000836, SIP callid 0001A4A0-DC86-1273-8749-2230B00AAA77-325543@10.176.48.36 [Nov 7 18:50:52] DEBUG[15336][C-0000083a]: res_rtp_asterisk.c:3906 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f6c780dd9a8' [Nov 7 18:50:52] DEBUG[25482]: res_config_odbc.c:87 custom_prepare: Skip: 0; SQL: SELECT * FROM DYN_SIP_PEERS WHERE ipaddr = ? AND port = ? [Nov 7 18:50:52] DEBUG[25482]: res_config_odbc.c:103 custom_prepare: Parameter 1 ('ipaddr') = '127.0.0.1' [Nov 7 18:50:52] DEBUG[25482]: res_config_odbc.c:103 custom_prepare: Parameter 2 ('port') = '5060' [Nov 7 18:50:52] DEBUG[25475]: devicestate.c:344 _ast_device_state: No provider found, checking channel drivers for SIP - Asterisk_CLE [Nov 7 18:50:52] DEBUG[25475]: chan_sip.c:29328 sip_devicestate: Checking device state for peer Asterisk_CLE [Nov 7 18:50:52] DEBUG[25475]: devicestate.c:467 do_state_change: Changing state for SIP/Asterisk_CLE - state 1 (Not in use) [Nov 7 18:50:52] DEBUG[25475]: devicestate.c:442 devstate_event: device 'SIP/Asterisk_CLE' state '1' [Nov 7 18:50:52] DEBUG[25487]: app_queue.c:1804 handle_statechange: Device 'SIP/Asterisk_CLE' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Nov 7 18:50:52] DEBUG[25482]: res_odbc.c:1053 odbc_release_obj2: odbc_release_obj2(0x7f6c480ee368) called (obj->txf = (nil)) [Nov 7 18:50:52] DEBUG[25482]: res_config_odbc.c:87 custom_prepare: Skip: 0; SQL: SELECT * FROM DYN_SIP_PEERS WHERE host = ? AND insecure LIKE ? ORDER BY host [Nov 7 18:50:52] DEBUG[25482]: res_config_odbc.c:103 custom_prepare: Parameter 1 ('host') = '127.0.0.1' [Nov 7 18:50:52] DEBUG[25482]: res_config_odbc.c:103 custom_prepare: Parameter 2 ('insecure LIKE') = '%port%' [Nov 7 18:50:52] DEBUG[25482]: res_odbc.c:1053 odbc_release_obj2: odbc_release_obj2(0x7f6c480ee368) called (obj->txf = (nil)) [Nov 7 18:50:52] DEBUG[25482]: res_config_odbc.c:87 custom_prepare: Skip: 0; SQL: SELECT * FROM DYN_SIP_PEERS WHERE ipaddr = ? AND insecure LIKE ? ORDER BY ipaddr [Nov 7 18:50:52] DEBUG[25482]: res_config_odbc.c:103 custom_prepare: Parameter 1 ('ipaddr') = '127.0.0.1' [Nov 7 18:50:52] DEBUG[25482]: res_config_odbc.c:103 custom_prepare: Parameter 2 ('insecure LIKE') = '%port%' [Nov 7 18:50:52] DEBUG[25482]: res_odbc.c:1053 odbc_release_obj2: odbc_release_obj2(0x7f6c480ee368) called (obj->txf = (nil)) [Nov 7 18:50:52] DEBUG[25482]: chan_sip.c:3869 __sip_xmit: Trying to put 'SIP/2.0 489' onto UDP socket destined for 127.0.0.1:5060 [Nov 7 18:50:52] DEBUG[25482]: chan_sip.c:28193 handle_request_do: SIP message could not be handled, bad request: 650572e4432bb6ff08e569b50f19e429@127.0.0.1:5060 [Nov 7 18:50:52] DEBUG[25482]: chan_sip.c:9123 find_call: = Looking for Call ID: 650572e4432bb6ff08e569b50f19e429@127.0.0.1:5060 (Checking To) --From tag as138134da --To-tag as4de1823f [Nov 7 18:50:52] DEBUG[25482]: chan_sip.c:4561 __sip_ack: Stopping retransmission on '650572e4432bb6ff08e569b50f19e429@127.0.0.1:5060' of Request 102: Match Found