[Feb 12 01:50:04] DEBUG[3607]: chan_sip.c:29297 sip_devicestate: Checking device state for peer 143
[Feb 12 01:50:04] DEBUG[3607]: devicestate.c:467 do_state_change: Changing state for SIP/143 - state 1 (Not in use)
[Feb 12 01:50:04] DEBUG[3607]: devicestate.c:442 devstate_event: device 'SIP/143' state '1'
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: logger.c:1324 ast_callid_threadassoc_add: CALL_ID [C-00000000] bound to thread.
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: pbx.c:4633 pbx_extension_helper: Launching 'Set'
    -- Executing [0124@extensions:1] Set("SIP/143-00000000", "URL=http://example.com/cgi-bin/avxml") in new stack
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: pbx.c:3639 ast_str_retrieve_variable: Result of 'IDNO' is NULL
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: pbx.c:4529 pbx_substitute_variables_helper_full: Expression result is '1'
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: pbx.c:4633 pbx_extension_helper: Launching 'GotoIf'
    -- Executing [0124@extensions:2] GotoIf("SIP/143-00000000", "1?macro") in new stack
    -- Goto (extensions,0124,4)
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: pbx.c:3642 ast_str_retrieve_variable: Result of 'URL' is 'http://example.com/cgi-bin/avxml'
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: pbx.c:4633 pbx_extension_helper: Launching 'Gosub'
    -- Executing [0124@extensions:4] Gosub("SIP/143-00000000", "VXML,s,1(http://example.com/cgi-bin/avxml)") in new stack
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: app_stack.c:578 gosub_exec: Channel SIP/143-00000000 has no datastore, so we're allocating one.
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: app_stack.c:620 gosub_exec: Setting 'ARG1' to 'http://example.com/cgi-bin/avxml'
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: pbx.c:4633 pbx_extension_helper: Launching 'Answer'
    -- Executing [s@VXML:1] Answer("SIP/143-00000000", "") in new stack
[Feb 12 01:50:04] DEBUG[3607]: devicestate.c:344 _ast_device_state: No provider found, checking channel drivers for SIP - 143
[Feb 12 01:50:04] DEBUG[3607]: chan_sip.c:29297 sip_devicestate: Checking device state for peer 143
[Feb 12 01:50:04] DEBUG[3607]: devicestate.c:467 do_state_change: Changing state for SIP/143 - state 1 (Not in use)
[Feb 12 01:50:04] DEBUG[3607]: devicestate.c:442 devstate_event: device 'SIP/143' state '1'
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: chan_sip.c:7256 sip_answer: SIP answering channel: SIP/143-00000000
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: res_rtp_asterisk.c:2085 ast_rtp_update_source: Setting the marker bit due to a source update
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: chan_sip.c:13504 transmit_response_with_sdp: Setting framing from config on incoming call
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: chan_sip.c:13054 add_sdp: ** Our capability: (ulaw) Video flag: True Text flag: True
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: chan_sip.c:13055 add_sdp: ** Our prefcodec: (nothing) 
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: chan_sip.c:13192 add_sdp: -- Done with adding codecs to SDP
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: chan_sip.c:13390 add_sdp: Done building SDP. Settling with this capability: (ulaw)
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: chan_sip.c:3864 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.0.0.10:1024
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: res_rtp_asterisk.c:3107 ast_rtcp_read: Got RTCP report of 132 bytes
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: res_rtp_asterisk.c:3502 ast_rtp_read: 0xb54e4b30 -- start learning mode pass with addr = 10.0.0.10:1026
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: res_rtp_asterisk.c:1605 rtp_learning_rtp_seq_update: 0xb54e4b30 -- probation = 4, seq = 5230
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: res_rtp_asterisk.c:3508 ast_rtp_read: 0xb54e4b30 -- Condition for learning hasn't exited, so reject the frame.
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: res_rtp_asterisk.c:3502 ast_rtp_read: 0xb54e4b30 -- start learning mode pass with addr = 10.0.0.10:1026
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: res_rtp_asterisk.c:1605 rtp_learning_rtp_seq_update: 0xb54e4b30 -- probation = 3, seq = 5231
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: res_rtp_asterisk.c:3508 ast_rtp_read: 0xb54e4b30 -- Condition for learning hasn't exited, so reject the frame.
[Feb 12 01:50:04] DEBUG[3622]: chan_sip.c:4128 retrans_pkt: ** SIP timers: Rescheduling retransmission 2 to 210 ms (t1 105 ms (Retrans id #260)) 
[Feb 12 01:50:04] DEBUG[3622]: chan_sip.c:3864 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.0.0.10:1024
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: res_rtp_asterisk.c:3502 ast_rtp_read: 0xb54e4b30 -- start learning mode pass with addr = 10.0.0.10:1026
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: res_rtp_asterisk.c:1605 rtp_learning_rtp_seq_update: 0xb54e4b30 -- probation = 2, seq = 5232
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: res_rtp_asterisk.c:3508 ast_rtp_read: 0xb54e4b30 -- Condition for learning hasn't exited, so reject the frame.
[Feb 12 01:50:04] DEBUG[3622]: chan_sip.c:9118 find_call: = Looking for  Call ID: NGI3YjY4NjE3MzY1NTM2ZGQ4ZTRhMTA1ZTA5NDUyZmI. (Checking From) --From tag 6638200b --To-tag as40edeb1b  
[Feb 12 01:50:04] DEBUG[3622][C-00000000]: logger.c:1324 ast_callid_threadassoc_add: CALL_ID [C-00000000] bound to thread.
[Feb 12 01:50:04] DEBUG[3622][C-00000000]: chan_sip.c:27866 handle_incoming: **** Received ACK (6) - Command in SIP ACK
[Feb 12 01:50:04] DEBUG[3622][C-00000000]: chan_sip.c:4556 __sip_ack: Stopping retransmission on 'NGI3YjY4NjE3MzY1NTM2ZGQ4ZTRhMTA1ZTA5NDUyZmI.' of Response 2: Match Found
[Feb 12 01:50:04] DEBUG[3622][C-00000000]: logger.c:1346 ast_callid_threadassoc_remove: Call_ID [C-00000000] being removed from thread.
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: res_rtp_asterisk.c:3502 ast_rtp_read: 0xb54e4b30 -- start learning mode pass with addr = 10.0.0.10:1026
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: res_rtp_asterisk.c:1605 rtp_learning_rtp_seq_update: 0xb54e4b30 -- probation = 1, seq = 5233
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: res_rtp_asterisk.c:3512 ast_rtp_read: 0xb54e4b30 -- Probation Ended. Set strict_rtp_state to STRICT_RTP_CLOSED with address 10.0.0.10:1026
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: res_rtp_asterisk.c:3896 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0xb54e0624'
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: dsp.c:583 tone_detect: tone 1100, Ew=9.42E+04, Et=6.38E+06, s/n=      0.01
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: pbx.c:3642 ast_str_retrieve_variable: Result of 'ARG1' is 'http://example.com/cgi-bin/avxml'
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: pbx.c:4461 pbx_substitute_variables_helper_full: Function result is 'http%3A%2F%2Fexample.com%2Fcgi-bin%2Favxml'
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: pbx.c:4633 pbx_extension_helper: Launching 'Set'
    -- Executing [s@VXML:2] Set("SIP/143-00000000", "ENCODED=http%3A%2F%2Fexample.com%2Fcgi-bin%2Favxml") in new stack
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: pbx.c:3642 ast_str_retrieve_variable: Result of 'ENCODED' is 'http%3A%2F%2Fexample.com%2Fcgi-bin%2Favxml'
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: pbx.c:4633 pbx_extension_helper: Launching 'AGI'
    -- Executing [s@VXML:3] AGI("SIP/143-00000000", "agi://localhost/url=http%3A%2F%2Fexample.com%2Fcgi-bin%2Favxml") in new stack
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting 'localhost' into...
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host 'localhost' and port ''.
[Feb 12 01:50:04] ERROR[3634][C-00000000]: utils.c:1187 ast_carefulwrite: write() returned error: Connection refused
[Feb 12 01:50:04] WARNING[3634][C-00000000]: res_agi.c:1528 launch_netscript: Connect to 'agi://localhost/url=http%3A%2F%2Fexample.com%2Fcgi-bin%2Favxml' failed: Connection refused
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: pbx.c:4633 pbx_extension_helper: Launching 'Hangup'
    -- Executing [s@VXML:4] Hangup("SIP/143-00000000", "") in new stack
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: channel.c:2657 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/143-00000000'
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: pbx.c:6316 __ast_pbx_run: Spawn extension (VXML,s,4) exited non-zero on 'SIP/143-00000000'
  == Spawn extension (VXML, s, 4) exited non-zero on 'SIP/143-00000000'
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: channel.c:2657 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/143-00000000'
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: channel.c:2836 ast_hangup: Hanging up channel 'SIP/143-00000000'
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: chan_sip.c:7049 sip_hangup: Hangup call SIP/143-00000000, SIP callid NGI3YjY4NjE3MzY1NTM2ZGQ4ZTRhMTA1ZTA5NDUyZmI.
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: res_rtp_asterisk.c:3896 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0xb54e0624'
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: res_rtp_asterisk.c:3896 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0xb5101c54'
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: chan_sip.c:28783 stop_session_timer: Session timer stopped: 258 - NGI3YjY4NjE3MzY1NTM2ZGQ4ZTRhMTA1ZTA5NDUyZmI.
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '10.0.0.10:1024' into...
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '10.0.0.10' and port '1024'.
[Feb 12 01:50:04] DEBUG[3634][C-00000000]: chan_sip.c:3864 __sip_xmit: Trying to put 'BYE sip:143' onto UDP socket destined for 10.0.0.10:1024
[Feb 12 01:50:04] DEBUG[3607]: devicestate.c:344 _ast_device_state: No provider found, checking channel drivers for SIP - 143
[Feb 12 01:50:04] DEBUG[3607]: chan_sip.c:29297 sip_devicestate: Checking device state for peer 143
[Feb 12 01:50:04] DEBUG[3607]: devicestate.c:467 do_state_change: Changing state for SIP/143 - state 1 (Not in use)
[Feb 12 01:50:04] DEBUG[3607]: devicestate.c:442 devstate_event: device 'SIP/143' state '1'
[Feb 12 01:50:04] DEBUG[3622]: chan_sip.c:9118 find_call: = Looking for  Call ID: NGI3YjY4NjE3MzY1NTM2ZGQ4ZTRhMTA1ZTA5NDUyZmI. (Checking From) --From tag 6638200b --To-tag as40edeb1b  
[Feb 12 01:50:04] DEBUG[3622][C-00000000]: logger.c:1324 ast_callid_threadassoc_add: CALL_ID [C-00000000] bound to thread.
[Feb 12 01:50:04] DEBUG[3622][C-00000000]: chan_sip.c:27866 handle_incoming: **** Received ACK (6) - Command in SIP ACK
[Feb 12 01:50:04] DEBUG[3622][C-00000000]: logger.c:1346 ast_callid_threadassoc_remove: Call_ID [C-00000000] being removed from thread.
[Feb 12 01:50:04] DEBUG[3622]: chan_sip.c:9118 find_call: = Looking for  Call ID: NGI3YjY4NjE3MzY1NTM2ZGQ4ZTRhMTA1ZTA5NDUyZmI. (Checking To) --From tag as40edeb1b --To-tag 6638200b  
[Feb 12 01:50:04] DEBUG[3622][C-00000000]: logger.c:1324 ast_callid_threadassoc_add: CALL_ID [C-00000000] bound to thread.
[Feb 12 01:50:04] DEBUG[3622][C-00000000]: chan_sip.c:4556 __sip_ack: Stopping retransmission on 'NGI3YjY4NjE3MzY1NTM2ZGQ4ZTRhMTA1ZTA5NDUyZmI.' of Request 102: Match Found
[Feb 12 01:50:04] DEBUG[3622][C-00000000]: logger.c:1346 ast_callid_threadassoc_remove: Call_ID [C-00000000] being removed from thread.
[Feb 12 01:50:04] DEBUG[3622]: chan_sip.c:6817 sip_destroy: Destroying SIP dialog NGI3YjY4NjE3MzY1NTM2ZGQ4ZTRhMTA1ZTA5NDUyZmI.
[Feb 12 01:50:04] DEBUG[3622]: rtp_engine.c:226 instance_destructor: Destroyed RTP instance '0xb54e0624'
[Feb 12 01:50:04] DEBUG[3622]: rtp_engine.c:226 instance_destructor: Destroyed RTP instance '0xb5101c54'