*CLI> [May 19 11:30:35] DEBUG[10736]: http.c:963 handle_uri: HTTP Request URI is /ari/events?app=demo [May 19 11:30:35] DEBUG[10736]: http.c:1013 handle_uri: match request [ari/events] with handler [httpstatus] len 10 [May 19 11:30:35] DEBUG[10736]: http.c:1013 handle_uri: match request [ari/events] with handler [phoneprov] len 9 [May 19 11:30:35] DEBUG[10736]: http.c:1013 handle_uri: match request [ari/events] with handler [static] len 6 [May 19 11:30:35] DEBUG[10736]: http.c:1013 handle_uri: match request [ari/events] with handler [ari] len 3 [May 19 11:30:35] DEBUG[10736]: http.c:1029 handle_uri: Match made with [ari] [May 19 11:30:35] DEBUG[10736]: res_ari.c:489 ast_ari_invoke: Finding handler for events [May 19 11:30:35] DEBUG[10736]: res_ari.c:493 ast_ari_invoke: Checking bridges [May 19 11:30:35] DEBUG[10736]: res_ari.c:493 ast_ari_invoke: Checking asterisk [May 19 11:30:35] DEBUG[10736]: res_ari.c:493 ast_ari_invoke: Checking channels [May 19 11:30:35] DEBUG[10736]: res_ari.c:493 ast_ari_invoke: Checking applications [May 19 11:30:35] DEBUG[10736]: res_ari.c:493 ast_ari_invoke: Checking events [May 19 11:30:35] DEBUG[10736]: res_ari.c:513 ast_ari_invoke: Got it! == WebSocket connection from '127.0.0.1:52065' for protocol '' accepted using version '13' [May 19 11:30:35] DEBUG[10736]: ari/resource_events.c:180 ast_ari_websocket_events_event_websocket: /events WebSocket connection Creating Stasis app 'demo' [May 19 11:30:40] DEBUG[10689]: chan_sip.c:9344 find_call: = Looking for Call ID: 1-10739@127.0.1.1 (Checking From) --From tag 10739SIPpTag001 --To-tag [May 19 11:30:40] DEBUG[10689]: acl.c:933 ast_ouraddrfor: For destination '127.0.0.1', our source address is '127.0.0.1'. [May 19 11:30:40] DEBUG[10689]: chan_sip.c:4101 ast_sip_ouraddrfor: Setting AST_TRANSPORT_UDP with address 127.0.0.1:5060 [May 19 11:30:40] DEBUG[10689]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '127.0.1.1:5061' into... [May 19 11:30:40] DEBUG[10689]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '127.0.1.1' and port '5061'. [May 19 11:30:40] DEBUG[10689]: chan_sip.c:18473 check_for_nat: NAT detected for 127.0.1.1 / 127.0.0.1 [May 19 11:30:40] DEBUG[10689]: chan_sip.c:8932 sip_alloc: Allocating new SIP dialog for 1-10739@127.0.1.1 - INVITE (No RTP) [May 19 11:30:40] DEBUG[10689][C-00000000]: chan_sip.c:28209 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE [May 19 11:30:40] DEBUG[10689][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '127.0.1.1:5061' into... [May 19 11:30:40] DEBUG[10689][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '127.0.1.1' and port '5061'. [May 19 11:30:40] DEBUG[10689][C-00000000]: chan_sip.c:18473 check_for_nat: NAT detected for 127.0.1.1 / 127.0.0.1 [May 19 11:30:40] DEBUG[10689][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '127.0.1.1:5061' into... [May 19 11:30:40] DEBUG[10689][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '127.0.1.1' and port ''. [May 19 11:30:40] DEBUG[10689][C-00000000]: rtp_engine.c:395 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7f97f000b918' [May 19 11:30:40] DEBUG[10689][C-00000000]: res_rtp_asterisk.c:1988 ast_rtp_new: Allocated port 12588 for RTP instance '0x7f97f000b918' [May 19 11:30:40] DEBUG[10689][C-00000000]: pjsip:0 : icess0x7f97f00 ICE session created, comp_cnt=2, role is Unknown agent [May 19 11:30:40] DEBUG[10689][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.0.72' into... [May 19 11:30:40] DEBUG[10689][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.0.72' and port ''. [May 19 11:30:40] DEBUG[10689][C-00000000]: pjsip:0 : icess0x7f97f00 Candidate 0 added: comp_id=1, type=host, foundation=Hc0a80048, addr=192.168.0.72:12588, base=192.168.0.72:12588, prio=0x7effffff (2130706431) [May 19 11:30:40] DEBUG[10689][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.122.1' into... [May 19 11:30:40] DEBUG[10689][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.122.1' and port ''. [May 19 11:30:40] DEBUG[10689][C-00000000]: pjsip:0 : icess0x7f97f00 Candidate 1 added: comp_id=1, type=host, foundation=Hc0a87a01, addr=192.168.122.1:12588, base=192.168.122.1:12588, prio=0x7effffff (2130706431) [May 19 11:30:40] DEBUG[10689][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.132.1' into... [May 19 11:30:40] DEBUG[10689][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.132.1' and port ''. [May 19 11:30:40] DEBUG[10689][C-00000000]: pjsip:0 : icess0x7f97f00 Candidate 2 added: comp_id=1, type=host, foundation=Hc0a88401, addr=192.168.132.1:12588, base=192.168.132.1:12588, prio=0x7effffff (2130706431) [May 19 11:30:40] DEBUG[10689][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.168.1' into... [May 19 11:30:40] DEBUG[10689][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.168.1' and port ''. [May 19 11:30:40] DEBUG[10689][C-00000000]: pjsip:0 : icess0x7f97f00 Candidate 3 added: comp_id=1, type=host, foundation=Hac10a801, addr=172.16.168.1:12588, base=172.16.168.1:12588, prio=0x7effffff (2130706431) [May 19 11:30:40] DEBUG[10689][C-00000000]: rtp_engine.c:404 ast_rtp_instance_new: RTP instance '0x7f97f000b918' is setup and ready to go [May 19 11:30:40] DEBUG[10689][C-00000000]: pjsip:0 : icess0x7f97f00 Destroying ICE session 0x7f97f0014368 [May 19 11:30:40] DEBUG[10689][C-00000000]: pjsip:0 : stuse0x7f97f00 STUN session 0x7f97f0016ba8 destroy request, ref_cnt=4 [May 19 11:30:40] DEBUG[10689][C-00000000]: pjsip:0 : stuse0x7f97f00 STUN session 0x7f97f0017ba8 destroy request, ref_cnt=3 [May 19 11:30:40] DEBUG[10689][C-00000000]: pjsip:0 : ice_session.c ICE session 0x7f97f0014368 destroyed [May 19 11:30:40] DEBUG[10689][C-00000000]: pjsip:0 : stun_session.c STUN session 0x7f97f0016ba8 destroyed [May 19 11:30:40] DEBUG[10689][C-00000000]: pjsip:0 : stun_session.c STUN session 0x7f97f0017ba8 destroyed [May 19 11:30:40] DEBUG[10689][C-00000000]: res_rtp_asterisk.c:4159 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7f97f000b918' == Using SIP RTP CoS mark 5 [May 19 11:30:40] DEBUG[10689][C-00000000]: chan_sip.c:5832 do_setnat: Setting NAT on RTP to Off [May 19 11:30:40] DEBUG[10689][C-00000000]: chan_sip.c:10161 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [May 19 11:30:40] DEBUG[10689][C-00000000]: chan_sip.c:10161 process_sdp: Processing session-level SDP o=user1 53655765 2353687637 IN IP4 127.0.1.1... OK. [May 19 11:30:40] DEBUG[10689][C-00000000]: chan_sip.c:10161 process_sdp: Processing session-level SDP s=-... UNSUPPORTED OR FAILED. [May 19 11:30:40] DEBUG[10689][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '127.0.1.1' into... [May 19 11:30:40] DEBUG[10689][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '127.0.1.1' and port ''. [May 19 11:30:40] DEBUG[10689][C-00000000]: chan_sip.c:10161 process_sdp: Processing session-level SDP c=IN IP4 127.0.1.1... OK. [May 19 11:30:40] DEBUG[10689][C-00000000]: chan_sip.c:10161 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [May 19 11:30:40] DEBUG[10689][C-00000000]: rtp_engine.c:665 ast_rtp_codecs_payloads_set_m_type: Setting payload 0 based on m type on 0x7f98040bcf40 [May 19 11:30:40] DEBUG[10689][C-00000000]: chan_sip.c:10608 process_sdp: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [May 19 11:30:40] DEBUG[10689][C-00000000]: res_rtp_asterisk.c:4206 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f97f000b918' [May 19 11:30:40] DEBUG[10689][C-00000000]: rtp_engine.c:623 ast_rtp_codecs_payloads_copy: Copying payload 0 from 0x7f98040bcf40 to 0x7f97f000ba58 [May 19 11:30:40] DEBUG[10689][C-00000000]: res_rtp_asterisk.c:4125 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7f97f000b918' [May 19 11:30:40] DEBUG[10689][C-00000000]: chan_sip.c:10879 process_sdp: We're settling with these formats: (ulaw) [May 19 11:30:40] DEBUG[10689][C-00000000]: chan_sip.c:25795 handle_request_invite: Checking SIP call limits for device [May 19 11:30:40] DEBUG[10689][C-00000000]: chan_sip.c:6790 update_call_counter: Updating call counter for incoming call [May 19 11:30:40] DEBUG[10689][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '127.0.0.1:5060' into... [May 19 11:30:40] DEBUG[10689][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '127.0.0.1' and port ''. [May 19 11:30:40] DEBUG[10689][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '127.0.1.1:5061' into... [May 19 11:30:40] DEBUG[10689][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '127.0.1.1' and port ''. [May 19 11:30:40] DEBUG[10689][C-00000000]: format_pref.c:375 ast_codec_choose: Could not find preferred codec - Going for the best codec [May 19 11:30:40] DEBUG[10689][C-00000000]: chan_sip.c:8112 sip_new: *** Our native formats are (ulaw) [May 19 11:30:40] DEBUG[10689][C-00000000]: chan_sip.c:8113 sip_new: *** Joint capabilities are (ulaw) [May 19 11:30:40] DEBUG[10689][C-00000000]: chan_sip.c:8114 sip_new: *** Our capabilities are (gsm|ulaw|alaw|h263|testlaw) [May 19 11:30:40] DEBUG[10689][C-00000000]: chan_sip.c:8115 sip_new: *** AST_CODEC_CHOOSE formats are ulaw [May 19 11:30:40] DEBUG[10689][C-00000000]: chan_sip.c:8143 sip_new: This channel will not be able to handle video. [May 19 11:30:40] DEBUG[10689][C-00000000]: chan_sip.c:16530 build_route: build_route: Contact hop: sip:sipp@127.0.1.1:5061 [May 19 11:30:40] DEBUG[10689][C-00000000]: chan_sip.c:26003 handle_request_invite: SIP/127.0.1.1-00000000: New call is still down.... Trying... [May 19 11:30:40] DEBUG[10689][C-00000000]: chan_sip.c:3944 __sip_xmit: Trying to put 'SIP/2.0 100' onto UDP socket destined for 127.0.0.1:5061 [May 19 11:30:40] DEBUG[10661]: devicestate.c:335 _ast_device_state: No provider found, checking channel drivers for SIP - 127.0.1.1 [May 19 11:30:40] DEBUG[10661]: chan_sip.c:29718 sip_devicestate: Checking device state for peer 127.0.1.1 [May 19 11:30:40] DEBUG[10661]: devicestate.c:431 do_state_change: Changing state for SIP/127.0.1.1 - state 4 (Invalid) [May 19 11:30:40] DEBUG[10740][C-00000000]: pbx.c:4869 pbx_extension_helper: Launching 'NoOp' -- Executing [service@default:1] NoOp("SIP/127.0.1.1-00000000", "") in new stack [May 19 11:30:40] DEBUG[10718]: app_queue.c:2366 device_state_cb: Device 'SIP/127.0.1.1' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [May 19 11:30:40] DEBUG[10740][C-00000000]: pbx.c:4869 pbx_extension_helper: Launching 'Stasis' -- Executing [service@default:2] Stasis("SIP/127.0.1.1-00000000", "demo,1") in new stack [May 19 11:30:40] DEBUG[10740][C-00000000]: ari/ari_websockets.c:165 ast_ari_websocket_session_write: Examining ARI event: {"application":"demo","type":"StasisStart","timestamp":"2014-05-19T11:30:40.959-0400","args":["1"],"channel":{"id":"1400513440.0","state":"Ring","name":"SIP/127.0.1.1-00000000","caller":{"name":"sipp","number":"sipp"},"connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"default","exten":"service","priority":2},"creationtime":"2014-05-19T11:30:40.958-0400"}} [May 19 11:30:40] DEBUG[10740][C-00000000]: stasis/app.c:971 app_subscribe_channel: Channel '1400513440.0' is 1 interested in demo [May 19 11:30:40] DEBUG[10741]: http.c:963 handle_uri: HTTP Request URI is /ari/channels/1400513440.0/answer [May 19 11:30:40] DEBUG[10741]: http.c:1013 handle_uri: match request [ari/channels/1400513440.0/answer] with handler [httpstatus] len 10 [May 19 11:30:40] DEBUG[10741]: http.c:1013 handle_uri: match request [ari/channels/1400513440.0/answer] with handler [phoneprov] len 9 [May 19 11:30:40] DEBUG[10741]: http.c:1013 handle_uri: match request [ari/channels/1400513440.0/answer] with handler [static] len 6 [May 19 11:30:40] DEBUG[10741]: http.c:1013 handle_uri: match request [ari/channels/1400513440.0/answer] with handler [ari] len 3 [May 19 11:30:40] DEBUG[10741]: http.c:1029 handle_uri: Match made with [ari] [May 19 11:30:40] DEBUG[10741]: res_ari.c:489 ast_ari_invoke: Finding handler for channels [May 19 11:30:40] DEBUG[10741]: res_ari.c:493 ast_ari_invoke: Checking bridges [May 19 11:30:40] DEBUG[10741]: res_ari.c:493 ast_ari_invoke: Checking asterisk [May 19 11:30:40] DEBUG[10741]: res_ari.c:493 ast_ari_invoke: Checking channels [May 19 11:30:40] DEBUG[10741]: res_ari.c:513 ast_ari_invoke: Got it! [May 19 11:30:40] DEBUG[10741]: res_ari.c:489 ast_ari_invoke: Finding handler for 1400513440.0 [May 19 11:30:40] DEBUG[10741]: res_ari.c:493 ast_ari_invoke: Checking channelId [May 19 11:30:40] DEBUG[10741]: res_ari.c:513 ast_ari_invoke: Got it! [May 19 11:30:40] DEBUG[10741]: res_ari.c:489 ast_ari_invoke: Finding handler for answer [May 19 11:30:40] DEBUG[10741]: res_ari.c:493 ast_ari_invoke: Checking continue [May 19 11:30:40] DEBUG[10741]: res_ari.c:493 ast_ari_invoke: Checking answer [May 19 11:30:40] DEBUG[10741]: res_ari.c:513 ast_ari_invoke: Got it! [May 19 11:30:40] DEBUG[10741]: res_stasis_answer.c:52 stasis_app_control_answer: 1400513440.0: Sending answer command [May 19 11:30:41] DEBUG[10689]: chan_sip.c:9344 find_call: = Looking for Call ID: 2-10739@127.0.1.1 (Checking From) --From tag 10739SIPpTag002 --To-tag [May 19 11:30:41] DEBUG[10689]: acl.c:933 ast_ouraddrfor: For destination '127.0.0.1', our source address is '127.0.0.1'. [May 19 11:30:41] DEBUG[10689]: chan_sip.c:4101 ast_sip_ouraddrfor: Setting AST_TRANSPORT_UDP with address 127.0.0.1:5060 [May 19 11:30:41] DEBUG[10689]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '127.0.1.1:5061' into... [May 19 11:30:41] DEBUG[10689]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '127.0.1.1' and port '5061'. [May 19 11:30:41] DEBUG[10689]: chan_sip.c:18473 check_for_nat: NAT detected for 127.0.1.1 / 127.0.0.1 [May 19 11:30:41] DEBUG[10689]: chan_sip.c:8932 sip_alloc: Allocating new SIP dialog for 2-10739@127.0.1.1 - INVITE (No RTP) [May 19 11:30:41] DEBUG[10689][C-00000001]: chan_sip.c:28209 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE [May 19 11:30:41] DEBUG[10689][C-00000001]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '127.0.1.1:5061' into... [May 19 11:30:41] DEBUG[10689][C-00000001]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '127.0.1.1' and port '5061'. [May 19 11:30:41] DEBUG[10689][C-00000001]: chan_sip.c:18473 check_for_nat: NAT detected for 127.0.1.1 / 127.0.0.1 [May 19 11:30:41] DEBUG[10689][C-00000001]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '127.0.1.1:5061' into... [May 19 11:30:41] DEBUG[10689][C-00000001]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '127.0.1.1' and port ''. [May 19 11:30:41] DEBUG[10689][C-00000001]: rtp_engine.c:395 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7f97f0021cf8' [May 19 11:30:41] DEBUG[10689][C-00000001]: res_rtp_asterisk.c:1988 ast_rtp_new: Allocated port 16416 for RTP instance '0x7f97f0021cf8' [May 19 11:30:41] DEBUG[10689][C-00000001]: pjsip:0 : icess0x7f97f00 ICE session created, comp_cnt=2, role is Unknown agent [May 19 11:30:41] DEBUG[10689][C-00000001]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.0.72' into... [May 19 11:30:41] DEBUG[10689][C-00000001]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.0.72' and port ''. [May 19 11:30:41] DEBUG[10689][C-00000001]: pjsip:0 : icess0x7f97f00 Candidate 0 added: comp_id=1, type=host, foundation=Hc0a80048, addr=192.168.0.72:16416, base=192.168.0.72:16416, prio=0x7effffff (2130706431) [May 19 11:30:41] DEBUG[10689][C-00000001]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.122.1' into... [May 19 11:30:41] DEBUG[10689][C-00000001]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.122.1' and port ''. [May 19 11:30:41] DEBUG[10689][C-00000001]: pjsip:0 : icess0x7f97f00 Candidate 1 added: comp_id=1, type=host, foundation=Hc0a87a01, addr=192.168.122.1:16416, base=192.168.122.1:16416, prio=0x7effffff (2130706431) [May 19 11:30:41] DEBUG[10689][C-00000001]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.132.1' into... [May 19 11:30:41] DEBUG[10689][C-00000001]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.132.1' and port ''. [May 19 11:30:41] DEBUG[10689][C-00000001]: pjsip:0 : icess0x7f97f00 Candidate 2 added: comp_id=1, type=host, foundation=Hc0a88401, addr=192.168.132.1:16416, base=192.168.132.1:16416, prio=0x7effffff (2130706431) [May 19 11:30:41] DEBUG[10689][C-00000001]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.168.1' into... [May 19 11:30:41] DEBUG[10689][C-00000001]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.168.1' and port ''. [May 19 11:30:41] DEBUG[10689][C-00000001]: pjsip:0 : icess0x7f97f00 Candidate 3 added: comp_id=1, type=host, foundation=Hac10a801, addr=172.16.168.1:16416, base=172.16.168.1:16416, prio=0x7effffff (2130706431) [May 19 11:30:41] DEBUG[10689][C-00000001]: rtp_engine.c:404 ast_rtp_instance_new: RTP instance '0x7f97f0021cf8' is setup and ready to go [May 19 11:30:41] DEBUG[10689][C-00000001]: pjsip:0 : icess0x7f97f00 Destroying ICE session 0x7f97f0028e88 [May 19 11:30:41] DEBUG[10689][C-00000001]: pjsip:0 : stuse0x7f97f00 STUN session 0x7f97f002ae98 destroy request, ref_cnt=4 [May 19 11:30:41] DEBUG[10689][C-00000001]: pjsip:0 : stuse0x7f97f00 STUN session 0x7f97f002b678 destroy request, ref_cnt=3 [May 19 11:30:41] DEBUG[10689][C-00000001]: pjsip:0 : ice_session.c ICE session 0x7f97f0028e88 destroyed [May 19 11:30:41] DEBUG[10689][C-00000001]: pjsip:0 : stun_session.c STUN session 0x7f97f002ae98 destroyed [May 19 11:30:41] DEBUG[10689][C-00000001]: pjsip:0 : stun_session.c STUN session 0x7f97f002b678 destroyed [May 19 11:30:41] DEBUG[10689][C-00000001]: res_rtp_asterisk.c:4159 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7f97f0021cf8' == Using SIP RTP CoS mark 5 [May 19 11:30:41] DEBUG[10689][C-00000001]: chan_sip.c:5832 do_setnat: Setting NAT on RTP to Off [May 19 11:30:41] DEBUG[10689][C-00000001]: chan_sip.c:10161 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [May 19 11:30:41] DEBUG[10689][C-00000001]: chan_sip.c:10161 process_sdp: Processing session-level SDP o=user1 53655765 2353687637 IN IP4 127.0.1.1... OK. [May 19 11:30:41] DEBUG[10689][C-00000001]: chan_sip.c:10161 process_sdp: Processing session-level SDP s=-... UNSUPPORTED OR FAILED. [May 19 11:30:41] DEBUG[10689][C-00000001]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '127.0.1.1' into... [May 19 11:30:41] DEBUG[10689][C-00000001]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '127.0.1.1' and port ''. [May 19 11:30:41] DEBUG[10689][C-00000001]: chan_sip.c:10161 process_sdp: Processing session-level SDP c=IN IP4 127.0.1.1... OK. [May 19 11:30:41] DEBUG[10689][C-00000001]: chan_sip.c:10161 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [May 19 11:30:41] DEBUG[10689][C-00000001]: rtp_engine.c:665 ast_rtp_codecs_payloads_set_m_type: Setting payload 0 based on m type on 0x7f98040bcf40 [May 19 11:30:41] DEBUG[10689][C-00000001]: chan_sip.c:10608 process_sdp: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [May 19 11:30:41] DEBUG[10689][C-00000001]: res_rtp_asterisk.c:4206 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f97f0021cf8' [May 19 11:30:41] DEBUG[10689][C-00000001]: rtp_engine.c:623 ast_rtp_codecs_payloads_copy: Copying payload 0 from 0x7f98040bcf40 to 0x7f97f0021e38 [May 19 11:30:41] DEBUG[10689][C-00000001]: res_rtp_asterisk.c:4125 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7f97f0021cf8' [May 19 11:30:41] DEBUG[10689][C-00000001]: chan_sip.c:10879 process_sdp: We're settling with these formats: (ulaw) [May 19 11:30:41] DEBUG[10689][C-00000001]: chan_sip.c:25795 handle_request_invite: Checking SIP call limits for device [May 19 11:30:41] DEBUG[10689][C-00000001]: chan_sip.c:6790 update_call_counter: Updating call counter for incoming call [May 19 11:30:41] DEBUG[10689][C-00000001]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '127.0.0.1:5060' into... [May 19 11:30:41] DEBUG[10689][C-00000001]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '127.0.0.1' and port ''. [May 19 11:30:41] DEBUG[10689][C-00000001]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '127.0.1.1:5061' into... [May 19 11:30:41] DEBUG[10689][C-00000001]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '127.0.1.1' and port ''. [May 19 11:30:41] DEBUG[10689][C-00000001]: format_pref.c:375 ast_codec_choose: Could not find preferred codec - Going for the best codec [May 19 11:30:41] DEBUG[10689][C-00000001]: chan_sip.c:8112 sip_new: *** Our native formats are (ulaw) [May 19 11:30:41] DEBUG[10689][C-00000001]: chan_sip.c:8113 sip_new: *** Joint capabilities are (ulaw) [May 19 11:30:41] DEBUG[10689][C-00000001]: chan_sip.c:8114 sip_new: *** Our capabilities are (gsm|ulaw|alaw|h263|testlaw) [May 19 11:30:41] DEBUG[10689][C-00000001]: chan_sip.c:8115 sip_new: *** AST_CODEC_CHOOSE formats are ulaw [May 19 11:30:41] DEBUG[10689][C-00000001]: chan_sip.c:8143 sip_new: This channel will not be able to handle video. [May 19 11:30:41] DEBUG[10689][C-00000001]: chan_sip.c:16530 build_route: build_route: Contact hop: sip:sipp@127.0.1.1:5061 [May 19 11:30:41] DEBUG[10689][C-00000001]: chan_sip.c:26003 handle_request_invite: SIP/127.0.1.1-00000001: New call is still down.... Trying... [May 19 11:30:41] DEBUG[10689][C-00000001]: chan_sip.c:3944 __sip_xmit: Trying to put 'SIP/2.0 100' onto UDP socket destined for 127.0.0.1:5061 [May 19 11:30:41] DEBUG[10661]: devicestate.c:335 _ast_device_state: No provider found, checking channel drivers for SIP - 127.0.1.1 [May 19 11:30:41] DEBUG[10661]: chan_sip.c:29718 sip_devicestate: Checking device state for peer 127.0.1.1 [May 19 11:30:41] DEBUG[10661]: devicestate.c:431 do_state_change: Changing state for SIP/127.0.1.1 - state 4 (Invalid) [May 19 11:30:41] DEBUG[10718]: app_queue.c:2366 device_state_cb: Device 'SIP/127.0.1.1' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [May 19 11:30:41] DEBUG[10742][C-00000001]: pbx.c:4869 pbx_extension_helper: Launching 'NoOp' -- Executing [service@default:1] NoOp("SIP/127.0.1.1-00000001", "") in new stack [May 19 11:30:41] DEBUG[10742][C-00000001]: pbx.c:4869 pbx_extension_helper: Launching 'Stasis' -- Executing [service@default:2] Stasis("SIP/127.0.1.1-00000001", "demo,1") in new stack [May 19 11:30:41] DEBUG[10742][C-00000001]: ari/ari_websockets.c:165 ast_ari_websocket_session_write: Examining ARI event: {"application":"demo","type":"StasisStart","timestamp":"2014-05-19T11:30:41.060-0400","args":["1"],"channel":{"id":"1400513441.1","state":"Ring","name":"SIP/127.0.1.1-00000001","caller":{"name":"sipp","number":"sipp"},"connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"default","exten":"service","priority":2},"creationtime":"2014-05-19T11:30:41.059-0400"}} [May 19 11:30:41] DEBUG[10742][C-00000001]: stasis/app.c:971 app_subscribe_channel: Channel '1400513441.1' is 1 interested in demo [May 19 11:30:41] DEBUG[10689]: chan_sip.c:9344 find_call: = Looking for Call ID: 3-10739@127.0.1.1 (Checking From) --From tag 10739SIPpTag003 --To-tag [May 19 11:30:41] DEBUG[10689]: acl.c:933 ast_ouraddrfor: For destination '127.0.0.1', our source address is '127.0.0.1'. [May 19 11:30:41] DEBUG[10689]: chan_sip.c:4101 ast_sip_ouraddrfor: Setting AST_TRANSPORT_UDP with address 127.0.0.1:5060 [May 19 11:30:41] DEBUG[10689]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '127.0.1.1:5061' into... [May 19 11:30:41] DEBUG[10689]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '127.0.1.1' and port '5061'. [May 19 11:30:41] DEBUG[10689]: chan_sip.c:18473 check_for_nat: NAT detected for 127.0.1.1 / 127.0.0.1 [May 19 11:30:41] DEBUG[10689]: chan_sip.c:8932 sip_alloc: Allocating new SIP dialog for 3-10739@127.0.1.1 - INVITE (No RTP) [May 19 11:30:41] DEBUG[10689][C-00000002]: chan_sip.c:28209 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE [May 19 11:30:41] DEBUG[10689][C-00000002]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '127.0.1.1:5061' into... [May 19 11:30:41] DEBUG[10689][C-00000002]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '127.0.1.1' and port '5061'. [May 19 11:30:41] DEBUG[10689][C-00000002]: chan_sip.c:18473 check_for_nat: NAT detected for 127.0.1.1 / 127.0.0.1 [May 19 11:30:41] DEBUG[10689][C-00000002]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '127.0.1.1:5061' into... [May 19 11:30:41] DEBUG[10689][C-00000002]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '127.0.1.1' and port ''. [May 19 11:30:41] DEBUG[10689][C-00000002]: rtp_engine.c:395 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7f97f0031a38' [May 19 11:30:41] DEBUG[10689][C-00000002]: res_rtp_asterisk.c:1988 ast_rtp_new: Allocated port 19694 for RTP instance '0x7f97f0031a38' [May 19 11:30:41] DEBUG[10689][C-00000002]: pjsip:0 : icess0x7f97f00 ICE session created, comp_cnt=2, role is Unknown agent [May 19 11:30:41] DEBUG[10689][C-00000002]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.0.72' into... [May 19 11:30:41] DEBUG[10689][C-00000002]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.0.72' and port ''. [May 19 11:30:41] DEBUG[10689][C-00000002]: pjsip:0 : icess0x7f97f00 Candidate 0 added: comp_id=1, type=host, foundation=Hc0a80048, addr=192.168.0.72:19694, base=192.168.0.72:19694, prio=0x7effffff (2130706431) [May 19 11:30:41] DEBUG[10689][C-00000002]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.122.1' into... [May 19 11:30:41] DEBUG[10689][C-00000002]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.122.1' and port ''. [May 19 11:30:41] DEBUG[10689][C-00000002]: pjsip:0 : icess0x7f97f00 Candidate 1 added: comp_id=1, type=host, foundation=Hc0a87a01, addr=192.168.122.1:19694, base=192.168.122.1:19694, prio=0x7effffff (2130706431) [May 19 11:30:41] DEBUG[10689][C-00000002]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '192.168.132.1' into... [May 19 11:30:41] DEBUG[10689][C-00000002]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '192.168.132.1' and port ''. [May 19 11:30:41] DEBUG[10689][C-00000002]: pjsip:0 : icess0x7f97f00 Candidate 2 added: comp_id=1, type=host, foundation=Hc0a88401, addr=192.168.132.1:19694, base=192.168.132.1:19694, prio=0x7effffff (2130706431) [May 19 11:30:41] DEBUG[10689][C-00000002]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '172.16.168.1' into... [May 19 11:30:41] DEBUG[10689][C-00000002]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '172.16.168.1' and port ''. [May 19 11:30:41] DEBUG[10689][C-00000002]: pjsip:0 : icess0x7f97f00 Candidate 3 added: comp_id=1, type=host, foundation=Hac10a801, addr=172.16.168.1:19694, base=172.16.168.1:19694, prio=0x7effffff (2130706431) [May 19 11:30:41] DEBUG[10689][C-00000002]: rtp_engine.c:404 ast_rtp_instance_new: RTP instance '0x7f97f0031a38' is setup and ready to go [May 19 11:30:41] DEBUG[10689][C-00000002]: pjsip:0 : icess0x7f97f00 Destroying ICE session 0x7f97f0039c88 [May 19 11:30:41] DEBUG[10689][C-00000002]: pjsip:0 : stuse0x7f97f00 STUN session 0x7f97f003c4c8 destroy request, ref_cnt=4 [May 19 11:30:41] DEBUG[10689][C-00000002]: pjsip:0 : stuse0x7f97f00 STUN session 0x7f97f003d4c8 destroy request, ref_cnt=3 [May 19 11:30:41] DEBUG[10689][C-00000002]: pjsip:0 : ice_session.c ICE session 0x7f97f0039c88 destroyed [May 19 11:30:41] DEBUG[10689][C-00000002]: pjsip:0 : stun_session.c STUN session 0x7f97f003c4c8 destroyed [May 19 11:30:41] DEBUG[10689][C-00000002]: pjsip:0 : stun_session.c STUN session 0x7f97f003d4c8 destroyed [May 19 11:30:41] DEBUG[10689][C-00000002]: res_rtp_asterisk.c:4159 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7f97f0031a38' == Using SIP RTP CoS mark 5 [May 19 11:30:41] DEBUG[10689][C-00000002]: chan_sip.c:5832 do_setnat: Setting NAT on RTP to Off [May 19 11:30:41] DEBUG[10689][C-00000002]: chan_sip.c:10161 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [May 19 11:30:41] DEBUG[10689][C-00000002]: chan_sip.c:10161 process_sdp: Processing session-level SDP o=user1 53655765 2353687637 IN IP4 127.0.1.1... OK. [May 19 11:30:41] DEBUG[10689][C-00000002]: chan_sip.c:10161 process_sdp: Processing session-level SDP s=-... UNSUPPORTED OR FAILED. [May 19 11:30:41] DEBUG[10689][C-00000002]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '127.0.1.1' into... [May 19 11:30:41] DEBUG[10689][C-00000002]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '127.0.1.1' and port ''. [May 19 11:30:41] DEBUG[10689][C-00000002]: chan_sip.c:10161 process_sdp: Processing session-level SDP c=IN IP4 127.0.1.1... OK. [May 19 11:30:41] DEBUG[10689][C-00000002]: chan_sip.c:10161 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [May 19 11:30:41] DEBUG[10689][C-00000002]: rtp_engine.c:665 ast_rtp_codecs_payloads_set_m_type: Setting payload 0 based on m type on 0x7f98040bcf40 [May 19 11:30:41] DEBUG[10689][C-00000002]: chan_sip.c:10608 process_sdp: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [May 19 11:30:41] DEBUG[10689][C-00000002]: res_rtp_asterisk.c:4206 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f97f0031a38' [May 19 11:30:41] DEBUG[10689][C-00000002]: rtp_engine.c:623 ast_rtp_codecs_payloads_copy: Copying payload 0 from 0x7f98040bcf40 to 0x7f97f0031b78 [May 19 11:30:41] DEBUG[10689][C-00000002]: res_rtp_asterisk.c:4125 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7f97f0031a38' [May 19 11:30:41] DEBUG[10689][C-00000002]: chan_sip.c:10879 process_sdp: We're settling with these formats: (ulaw) [May 19 11:30:41] DEBUG[10689][C-00000002]: chan_sip.c:25795 handle_request_invite: Checking SIP call limits for device [May 19 11:30:41] DEBUG[10689][C-00000002]: chan_sip.c:6790 update_call_counter: Updating call counter for incoming call [May 19 11:30:41] DEBUG[10689][C-00000002]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '127.0.0.1:5060' into... [May 19 11:30:41] DEBUG[10689][C-00000002]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '127.0.0.1' and port ''. [May 19 11:30:41] DEBUG[10689][C-00000002]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '127.0.1.1:5061' into... [May 19 11:30:41] DEBUG[10689][C-00000002]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '127.0.1.1' and port ''. [May 19 11:30:41] DEBUG[10689][C-00000002]: format_pref.c:375 ast_codec_choose: Could not find preferred codec - Going for the best codec [May 19 11:30:41] DEBUG[10689][C-00000002]: chan_sip.c:8112 sip_new: *** Our native formats are (ulaw) [May 19 11:30:41] DEBUG[10689][C-00000002]: chan_sip.c:8113 sip_new: *** Joint capabilities are (ulaw) [May 19 11:30:41] DEBUG[10689][C-00000002]: chan_sip.c:8114 sip_new: *** Our capabilities are (gsm|ulaw|alaw|h263|testlaw) [May 19 11:30:41] DEBUG[10689][C-00000002]: chan_sip.c:8115 sip_new: *** AST_CODEC_CHOOSE formats are ulaw [May 19 11:30:41] DEBUG[10689][C-00000002]: chan_sip.c:8143 sip_new: This channel will not be able to handle video. [May 19 11:30:41] DEBUG[10689][C-00000002]: chan_sip.c:16530 build_route: build_route: Contact hop: sip:sipp@127.0.1.1:5061 [May 19 11:30:41] DEBUG[10689][C-00000002]: chan_sip.c:26003 handle_request_invite: SIP/127.0.1.1-00000002: New call is still down.... Trying... [May 19 11:30:41] DEBUG[10689][C-00000002]: chan_sip.c:3944 __sip_xmit: Trying to put 'SIP/2.0 100' onto UDP socket destined for 127.0.0.1:5061 [May 19 11:30:41] DEBUG[10661]: devicestate.c:335 _ast_device_state: No provider found, checking channel drivers for SIP - 127.0.1.1 [May 19 11:30:41] DEBUG[10661]: chan_sip.c:29718 sip_devicestate: Checking device state for peer 127.0.1.1 [May 19 11:30:41] DEBUG[10661]: devicestate.c:431 do_state_change: Changing state for SIP/127.0.1.1 - state 4 (Invalid) [May 19 11:30:41] DEBUG[10743][C-00000002]: pbx.c:4869 pbx_extension_helper: Launching 'NoOp' [May 19 11:30:41] DEBUG[10718]: app_queue.c:2366 device_state_cb: Device 'SIP/127.0.1.1' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. -- Executing [service@default:1] NoOp("SIP/127.0.1.1-00000002", "") in new stack [May 19 11:30:41] DEBUG[10743][C-00000002]: pbx.c:4869 pbx_extension_helper: Launching 'Stasis' -- Executing [service@default:2] Stasis("SIP/127.0.1.1-00000002", "demo,1") in new stack [May 19 11:30:41] DEBUG[10743][C-00000002]: ari/ari_websockets.c:165 ast_ari_websocket_session_write: Examining ARI event: {"application":"demo","type":"StasisStart","timestamp":"2014-05-19T11:30:41.159-0400","args":["1"],"channel":{"id":"1400513441.2","state":"Ring","name":"SIP/127.0.1.1-00000002","caller":{"name":"sipp","number":"sipp"},"connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"default","exten":"service","priority":2},"creationtime":"2014-05-19T11:30:41.158-0400"}} [May 19 11:30:41] DEBUG[10743][C-00000002]: stasis/app.c:971 app_subscribe_channel: Channel '1400513441.2' is 1 interested in demo [May 19 11:30:41] DEBUG[10740][C-00000000]: res_stasis_answer.c:43 app_control_answer: 1400513440.0: Answering [May 19 11:30:41] DEBUG[10738]: ari/ari_websockets.c:165 ast_ari_websocket_session_write: Examining ARI event: {"application":"demo","type":"ChannelStateChange","timestamp":"2014-05-19T11:30:41.159-0400","channel":{"id":"1400513440.0","state":"Up","name":"SIP/127.0.1.1-00000000","caller":{"name":"sipp","number":"sipp"},"connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"default","exten":"service","priority":2},"creationtime":"2014-05-19T11:30:40.958-0400"}} [May 19 11:30:41] DEBUG[10740][C-00000000]: chan_sip.c:7408 sip_answer: SIP answering channel: SIP/127.0.1.1-00000000 [May 19 11:30:41] DEBUG[10661]: devicestate.c:335 _ast_device_state: No provider found, checking channel drivers for SIP - 127.0.1.1 [May 19 11:30:41] DEBUG[10740][C-00000000]: res_rtp_asterisk.c:2345 ast_rtp_update_source: Setting the marker bit due to a source update [May 19 11:30:41] DEBUG[10661]: chan_sip.c:29718 sip_devicestate: Checking device state for peer 127.0.1.1 [May 19 11:30:41] DEBUG[10661]: devicestate.c:431 do_state_change: Changing state for SIP/127.0.1.1 - state 4 (Invalid) [May 19 11:30:41] DEBUG[10740][C-00000000]: chan_sip.c:13785 transmit_response_with_sdp: Setting framing from config on incoming call [May 19 11:30:41] DEBUG[10718]: app_queue.c:2366 device_state_cb: Device 'SIP/127.0.1.1' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [May 19 11:30:41] DEBUG[10740][C-00000000]: chan_sip.c:13323 add_sdp: ** Our capability: (ulaw) Video flag: True Text flag: True [May 19 11:30:41] DEBUG[10740][C-00000000]: chan_sip.c:13324 add_sdp: ** Our prefcodec: (nothing) [May 19 11:30:41] DEBUG[10740][C-00000000]: chan_sip.c:13469 add_sdp: -- Done with adding codecs to SDP [May 19 11:30:41] DEBUG[10740][C-00000000]: chan_sip.c:13671 add_sdp: Done building SDP. Settling with this capability: (ulaw) [May 19 11:30:41] DEBUG[10740][C-00000000]: chan_sip.c:3944 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 127.0.0.1:5061 [May 19 11:30:41] DEBUG[10689]: chan_sip.c:9344 find_call: = Looking for Call ID: 1-10739@127.0.1.1 (Checking From) --From tag 10739SIPpTag001 --To-tag as11529974 [May 19 11:30:41] DEBUG[10689][C-00000000]: chan_sip.c:28209 handle_incoming: **** Received ACK (6) - Command in SIP ACK [May 19 11:30:41] DEBUG[10689][C-00000000]: chan_sip.c:4636 __sip_ack: Stopping retransmission on '1-10739@127.0.1.1' of Response 1: Match Found [May 19 11:30:41] DEBUG[10689]: chan_sip.c:9344 find_call: = Looking for Call ID: 1-10739@127.0.1.1 (Checking From) --From tag 10739SIPpTag001 --To-tag as11529974 [May 19 11:30:41] DEBUG[10689][C-00000000]: chan_sip.c:28209 handle_incoming: **** Received BYE (8) - Command in SIP BYE [May 19 11:30:41] DEBUG[10689][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '127.0.1.1:5061' into... [May 19 11:30:41] DEBUG[10689][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '127.0.1.1' and port '5061'. [May 19 11:30:41] DEBUG[10689][C-00000000]: chan_sip.c:18473 check_for_nat: NAT detected for 127.0.1.1 / 127.0.0.1 [May 19 11:30:41] DEBUG[10689][C-00000000]: chan_sip.c:3600 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 1-10739@127.0.1.1 [May 19 11:30:41] DEBUG[10738]: ari/ari_websockets.c:165 ast_ari_websocket_session_write: Examining ARI event: {"channel":{"id":"1400513440.0","state":"Up","name":"SIP/127.0.1.1-00000000","caller":{"name":"sipp","number":"sipp"},"connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"default","exten":"service","priority":2},"creationtime":"2014-05-19T11:30:40.958-0400"},"application":"demo","variable":"RTPAUDIOQOS","type":"ChannelVarset","value":"ssrc=1010467557;themssrc=0;lp=0;rxjitter=0.000000;rxcount=0;txjitter=0.000000;txcount=0;rlp=0;rtt=0.000000","timestamp":"2014-05-19T11:30:41.162-0400"} [May 19 11:30:41] DEBUG[10738]: ari/ari_websockets.c:165 ast_ari_websocket_session_write: Examining ARI event: {"channel":{"id":"1400513440.0","state":"Up","name":"SIP/127.0.1.1-00000000","caller":{"name":"sipp","number":"sipp"},"connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"default","exten":"service","priority":2},"creationtime":"2014-05-19T11:30:40.958-0400"},"application":"demo","variable":"RTPAUDIOQOSJITTER","type":"ChannelVarset","value":"minrxjitter=0.000000;maxrxjitter=0.000000;avgrxjitter=0.000000;stdevrxjitter=0.000000;reported_minjitter=0.000000;reported_maxjitter=0.000000;reported_avgjitter=0.000000;reported_stdevjitter=0.000000;","timestamp":"2014-05-19T11:30:41.163-0400"} [May 19 11:30:41] DEBUG[10689][C-00000000]: res_rtp_asterisk.c:4206 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f97f000b918' [May 19 11:30:41] DEBUG[10738]: ari/ari_websockets.c:165 ast_ari_websocket_session_write: Examining ARI event: {"channel":{"id":"1400513440.0","state":"Up","name":"SIP/127.0.1.1-00000000","caller":{"name":"sipp","number":"sipp"},"connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"default","exten":"service","priority":2},"creationtime":"2014-05-19T11:30:40.958-0400"},"application":"demo","variable":"RTPAUDIOQOSLOSS","type":"ChannelVarset","value":"minrxlost=0.000000;maxrxlost=0.000000;avgrxlost=0.000000;stdevrxlost=0.000000;reported_minlost=0.000000;reported_maxlost=0.000000;reported_avglost=0.000000;reported_stdevlost=0.000000;","timestamp":"2014-05-19T11:30:41.163-0400"} [May 19 11:30:41] DEBUG[10689][C-00000000]: chan_sip.c:26825 handle_request_bye: Received bye, issuing owner hangup [May 19 11:30:41] DEBUG[10738]: ari/ari_websockets.c:165 ast_ari_websocket_session_write: Examining ARI event: {"channel":{"id":"1400513440.0","state":"Up","name":"SIP/127.0.1.1-00000000","caller":{"name":"sipp","number":"sipp"},"connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"default","exten":"service","priority":2},"creationtime":"2014-05-19T11:30:40.958-0400"},"application":"demo","variable":"RTPAUDIOQOSRTT","type":"ChannelVarset","value":"minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000;","timestamp":"2014-05-19T11:30:41.163-0400"} [May 19 11:30:41] DEBUG[10689][C-00000000]: chan_sip.c:3944 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 127.0.0.1:5061 [May 19 11:30:41] DEBUG[10740][C-00000000]: channel.c:2858 __ast_answer: Hangup of channel SIP/127.0.1.1-00000000 detected in answer routine [May 19 11:30:41] DEBUG[10740][C-00000000]: stasis/app.c:995 unsubscribe: channel '1400513440.0': is 0 interested in demo [May 19 11:30:41] DEBUG[10740][C-00000000]: stasis/app.c:998 unsubscribe: channel '1400513440.0' unsubscribed from demo [May 19 11:30:41] DEBUG[10738]: ari/ari_websockets.c:165 ast_ari_websocket_session_write: Examining ARI event: {"application":"demo","type":"ChannelHangupRequest","timestamp":"2014-05-19T11:30:41.163-0400","channel":{"id":"1400513440.0","state":"Up","name":"SIP/127.0.1.1-00000000","caller":{"name":"sipp","number":"sipp"},"connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"default","exten":"service","priority":2},"creationtime":"2014-05-19T11:30:40.958-0400"}} [May 19 11:30:41] WARNING[10741]: res_stasis_answer.c:57 stasis_app_control_answer: 1400513440.0: Failed to answer channel [May 19 11:30:41] WARNING[10741]: res_stasis_answer.c:57 stasis_app_control_answer: 1400513440.0: Failed to answer channel [May 19 11:30:41] DEBUG[10741]: res_ari.c:982 ast_ari_callback: Examining ARI response: 500 Internal Server Error Content-type: application/json {"message":"Failed to answer channel"} [May 19 11:30:41] DEBUG[10740][C-00000000]: ari/ari_websockets.c:165 ast_ari_websocket_session_write: Examining ARI event: {"application":"demo","type":"StasisEnd","timestamp":"2014-05-19T11:30:41.163-0400","channel":{"id":"1400513440.0","state":"Up","name":"SIP/127.0.1.1-00000000","caller":{"name":"sipp","number":"sipp"},"connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"default","exten":"service","priority":2},"creationtime":"2014-05-19T11:30:40.958-0400"}} [May 19 11:30:41] DEBUG[10740][C-00000000]: pbx.c:6339 __ast_pbx_run: Extension service, priority 2 returned normally even though call was hung up [May 19 11:30:41] DEBUG[10740][C-00000000]: channel.c:2599 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/127.0.1.1-00000000' [May 19 11:30:41] DEBUG[10740][C-00000000]: channel.c:2755 ast_hangup: Hanging up channel 'SIP/127.0.1.1-00000000' [May 19 11:30:41] DEBUG[10740][C-00000000]: chan_sip.c:7173 sip_hangup: Hangup call SIP/127.0.1.1-00000000, SIP callid 1-10739@127.0.1.1 [May 19 11:30:41] DEBUG[10740][C-00000000]: res_rtp_asterisk.c:4206 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f97f000b918' [May 19 11:30:41] DEBUG[10663]: cdr.c:1267 cdr_object_finalize: Finalized CDR for SIP/127.0.1.1-00000000 - start 1400513440.958337 answer 1400513441.159994 end 1400513441.164164 dispo ANSWERED