Nov 6 02:50:14 DEBUG[6922]: chan_sip.c:3082 sip_alloc: Allocating new SIP dialog for c45eada8-60280992-af9c172b@198.151.161.137 - INVITE (With RTP) Nov 6 02:50:14 DEBUG[6922]: chan_sip.c:1005 parse_sip_options: * SIP extension value: 2 for call c45eada8-60280992-af9c172b@198.151.161.137 Nov 6 02:50:14 DEBUG[6922]: chan_sip.c:6990 check_user_full: Setting NAT on RTP to 0 Nov 6 02:50:15 DEBUG[6922]: chan_sip.c:1370 __sip_ack: Stopping retransmission on 'c45eada8-60280992-af9c172b@198.151.161.137' of Response 1: Match Found Nov 6 02:50:15 DEBUG[6922]: chan_sip.c:6990 check_user_full: Setting NAT on RTP to 0 Nov 6 02:50:15 DEBUG[6922]: chan_sip.c:10298 handle_request_invite: Checking SIP call limits for device 2000 Nov 6 02:50:15 DEBUG[6922]: chan_sip.c:6005 build_route: build_route: Contact hop: Nov 6 02:50:15 DEBUG[6937]: pbx.c:1682 pbx_extension_helper: Launching 'Answer' -- Executing Answer("SIP/2000-c6bc", "") in new stack Nov 6 02:50:15 DEBUG[6938]: app_queue.c:443 changethread: Device 'SIP/2000' changed to state '2' (In use) Nov 6 02:50:15 DEBUG[6937]: chan_sip.c:2486 sip_answer: sip_answer(SIP/2000-c6bc) Nov 6 02:50:15 DEBUG[6916]: channel.c:769 channel_find_locked: Avoiding initial deadlock for 'SIP/2000-c6bc' Nov 6 02:50:15 DEBUG[6937]: pbx.c:1682 pbx_extension_helper: Launching 'AGI' -- Executing AGI("SIP/2000-c6bc", "agi-test.agi") in new stack -- Launched AGI Script /var/lib/asterisk/agi-bin/agi-test.agi Nov 6 02:50:15 DEBUG[6940]: app_queue.c:443 changethread: Device 'SIP/2000' changed to state '2' (In use) AGI Environment Dump: -- accountcode = -- callerid = 2000 -- calleridname = 2000 -- callingani2 = 0 -- callingpres = 0 -- callingtns = 0 -- callington = 0 -- channel = SIP/2000-c6bc -- context = internal -- dnid = 622 -- enhanced = 0.0 -- extension = 622 -- language = en -- priority = 2 -- rdnis = unknown -- request = agi-test.agi -- type = SIP -- uniqueid = 1131274215.1 1. Testing 'sendfile'...Nov 6 02:50:15 DEBUG[6937]: channel.c:2330 set_format: Set channel SIP/2000-c6bc to write format gsm Nov 6 02:50:15 DEBUG[6937]: rtp.c:1339 ast_rtp_write: Ooh, format changed from unknown to ulaw Nov 6 02:50:15 DEBUG[6937]: channel.c:1695 ast_settimeout: Scheduling timer at 160 sample intervals Nov 6 02:50:15 DEBUG[6922]: chan_sip.c:1370 __sip_ack: Stopping retransmission on 'c45eada8-60280992-af9c172b@198.151.161.137' of Response 2: Match Found Nov 6 02:50:15 DEBUG[6937]: channel.c:1695 ast_settimeout: Scheduling timer at 0 sample intervals Nov 6 02:50:15 DEBUG[6937]: channel.c:1695 ast_settimeout: Scheduling timer at 0 sample intervals Nov 6 02:50:15 DEBUG[6937]: channel.c:2330 set_format: Set channel SIP/2000-c6bc to write format ulaw PASS (0) 2. Testing 'sendtext'...PASS (0) 3. Testing 'sendimage'...PASS (0) 4. SKIPPING 'saynumber'... 5. Testing 'waitdtmf'...Nov 6 02:50:15 DEBUG[6922]: chan_sip.c:1370 __sip_ack: Stopping retransmission on 'c45eada8-60280992-af9c172b@198.151.161.137' of Request 102: Match Found PASS (0) 6. Testing 'record'...PASS (0) Nov 6 02:50:19 DEBUG[6937]: channel.c:1695 ast_settimeout: 6a. Testing 'record' playback...Scheduling timer at 0 sample intervals Nov 6 02:50:19 DEBUG[6937]: channel.c:2330 set_format: Set channel SIP/2000-c6bc to write format gsm Nov 6 02:50:19 DEBUG[6937]: channel.c:1695 ast_settimeout: Scheduling timer at 160 sample intervals Nov 6 02:50:22 DEBUG[6937]: channel.c:1695 ast_settimeout: Scheduling timer at 0 sample intervals Nov 6 02:50:22 DEBUG[6937]: channel.c:1695 ast_settimeout: Scheduling timer at 0 sample intervals Nov 6 02:50:22 DEBUG[6937]: channel.c:2330 set_format: Set channel SIP/2000-c6bc to write format ulaw PASS (0) ================== Complete ====================== 6 tests completed, 6 passed, 0 failed ================================================== -- AGI Script agi-test.agi completed, returning 0 Nov 6 02:50:22 DEBUG[6937]: pbx.c:1682 pbx_extension_helper: Launching 'Hangup' -- Executing Hangup("SIP/2000-c6bc", "") in new stack Nov 6 02:50:22 DEBUG[6937]: pbx.c:2321 __ast_pbx_run: Spawn extension (internal,622,3) exited non-zero on 'SIP/2000-c6bc' Nov 6 02:50:22 DEBUG[6937]: pbx.c:1527 pbx_substitute_variables_helper_full: Function result is '"2000" <2000>' Nov 6 02:50:22 DEBUG[6937]: pbx.c:1527 pbx_substitute_variables_helper_full: Function result is '2000' Nov 6 02:50:22 DEBUG[6937]: pbx.c:1527 pbx_substitute_variables_helper_full: Function result is '622' Nov 6 02:50:22 DEBUG[6937]: pbx.c:1527 pbx_substitute_variables_helper_full: Function result is 'internal' Nov 6 02:50:22 DEBUG[6937]: pbx.c:1527 pbx_substitute_variables_helper_full: Function result is 'SIP/2000-c6bc' Nov 6 02:50:22 DEBUG[6937]: pbx.c:1527 pbx_substitute_variables_helper_full: Function result is '(null)' Nov 6 02:50:22 DEBUG[6937]: pbx.c:1527 pbx_substitute_variables_helper_full: Function result is 'Hangup' Nov 6 02:50:22 DEBUG[6937]: pbx.c:1527 pbx_substitute_variables_helper_full: Function result is '(null)' Nov 6 02:50:22 DEBUG[6937]: pbx.c:1527 pbx_substitute_variables_helper_full: Function result is '2005-11-06 02:50:15' Nov 6 02:50:22 DEBUG[6937]: pbx.c:1527 pbx_substitute_variables_helper_full: Function result is '2005-11-06 02:50:15' Nov 6 02:50:22 DEBUG[6937]: pbx.c:1527 pbx_substitute_variables_helper_full: Function result is '2005-11-06 02:50:22' Nov 6 02:50:22 DEBUG[6937]: pbx.c:1527 pbx_substitute_variables_helper_full: Function result is '7' Nov 6 02:50:22 DEBUG[6937]: pbx.c:1527 pbx_substitute_variables_helper_full: Function result is '7' Nov 6 02:50:22 DEBUG[6937]: pbx.c:1527 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' Nov 6 02:50:22 DEBUG[6937]: pbx.c:1527 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' Nov 6 02:50:22 DEBUG[6937]: pbx.c:1527 pbx_substitute_variables_helper_full: Function result is '(null)' Nov 6 02:50:22 DEBUG[6937]: pbx.c:1527 pbx_substitute_variables_helper_full: Function result is '1131274215.1' Nov 6 02:50:22 DEBUG[6937]: pbx.c:1527 pbx_substitute_variables_helper_full: Function result is '(null)' Nov 6 02:50:22 DEBUG[6937]: channel.c:1307 ast_hangup: Hanging up channel 'SIP/2000-c6bc' Nov 6 02:50:22 DEBUG[6937]: chan_sip.c:2382 sip_hangup: Hangup call SIP/2000-c6bc, SIP callid c45eada8-60280992-af9c172b@198.151.161.137) Nov 6 02:50:22 DEBUG[6937]: chan_sip.c:2390 sip_hangup: update_call_counter(2000) - decrement call limit counter Nov 6 02:50:22 DEBUG[6941]: app_queue.c:443 changethread: Device 'SIP/2000' changed to state '1' (Not in use) Nov 6 02:50:22 DEBUG[6922]: chan_sip.c:1370 __sip_ack: Stopping retransmission on 'c45eada8-60280992-af9c172b@198.151.161.137' of Request 103: Match Found -- Incoming call: Got SIP response 500 "Internal Server Error" back from 198.151.161.137