May 12 16:08:06] NOTICE[24008] res_ari.c: Origin header 'localhost:8088' does not match an allowed origin. [May 12 16:08:06] VERBOSE[24008] stasis/app.c: Creating Stasis app 'test-ari' [May 12 16:08:06] VERBOSE[24008] res_http_websocket.c: WebSocket connection from '127.0.0.1:38249' for protocol '' accepted using version '13' [May 12 16:08:06] VERBOSE[24008] stasis/app.c: Activating Stasis app 'test-ari' [May 12 16:08:19] DEBUG[23508] chan_sip.c: = Looking for Call ID: 663848766 (Checking From) --From tag 1790999805 --To-tag [May 12 16:08:19] DEBUG[23508] acl.c: For destination '192.168.1.140', our source address is '192.168.1.141'. [May 12 16:08:19] DEBUG[23508] chan_sip.c: Setting AST_TRANSPORT_UDP with address 192.168.1.141:5060 [May 12 16:08:19] DEBUG[23508] netsock2.c: Splitting '192.168.1.140:5060' into... [May 12 16:08:19] DEBUG[23508] netsock2.c: ...host '192.168.1.140' and port '5060'. [May 12 16:08:19] DEBUG[23508] chan_sip.c: Allocating new SIP dialog for 663848766 - INVITE (No RTP) [May 12 16:08:19] DEBUG[23508][C-00000000] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [May 12 16:08:19] DEBUG[23508][C-00000000] netsock2.c: Splitting '192.168.1.140:5060' into... [May 12 16:08:19] DEBUG[23508][C-00000000] netsock2.c: ...host '192.168.1.140' and port '5060'. [May 12 16:08:19] DEBUG[23508][C-00000000] netsock2.c: Splitting '192.168.1.141' into... [May 12 16:08:19] DEBUG[23508][C-00000000] netsock2.c: ...host '192.168.1.141' and port ''. [May 12 16:08:19] DEBUG[23508][C-00000000] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.1.140:5060 [May 12 16:08:19] DEBUG[23508] chan_sip.c: = Looking for Call ID: 663848766 (Checking From) --From tag 1790999805 --To-tag as5386a6f1 [May 12 16:08:19] DEBUG[23508][C-00000000] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [May 12 16:08:19] DEBUG[23508][C-00000000] chan_sip.c: Stopping retransmission on '663848766' of Response 20: Match Found [May 12 16:08:19] DEBUG[23508] chan_sip.c: = Looking for Call ID: 663848766 (Checking From) --From tag 1790999805 --To-tag [May 12 16:08:19] DEBUG[23508] netsock2.c: Splitting '192.168.1.141' into... [May 12 16:08:19] DEBUG[23508] netsock2.c: ...host '192.168.1.141' and port ''. [May 12 16:08:19] DEBUG[23508] netsock2.c: Splitting '192.168.1.141' into... [May 12 16:08:19] DEBUG[23508] netsock2.c: ...host '192.168.1.141' and port ''. [May 12 16:08:19] DEBUG[23508][C-00000000] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [May 12 16:08:19] DEBUG[23508][C-00000000] netsock2.c: Splitting '192.168.1.140:5060' into... [May 12 16:08:19] DEBUG[23508][C-00000000] netsock2.c: ...host '192.168.1.140' and port '5060'. [May 12 16:08:19] DEBUG[23508][C-00000000] netsock2.c: Splitting '192.168.1.141' into... [May 12 16:08:19] DEBUG[23508][C-00000000] netsock2.c: ...host '192.168.1.141' and port ''. [May 12 16:08:19] DEBUG[23508][C-00000000] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x1ecd848' [May 12 16:08:19] DEBUG[23508][C-00000000] res_rtp_asterisk.c: Allocated port 13516 for RTP instance '0x1ecd848' [May 12 16:08:19] DEBUG[23508][C-00000000] rtp_engine.c: RTP instance '0x1ecd848' is setup and ready to go [May 12 16:08:19] DEBUG[23508][C-00000000] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x1ecd848' [May 12 16:08:19] VERBOSE[23508][C-00000000] netsock2.c: Using SIP RTP CoS mark 5 [May 12 16:08:19] DEBUG[23508][C-00000000] chan_sip.c: Setting NAT on RTP to Off [May 12 16:08:19] DEBUG[23508][C-00000000] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [May 12 16:08:19] DEBUG[23508][C-00000000] chan_sip.c: Processing session-level SDP o=100 3068 1233 IN IP4 192.168.1.140... OK. [May 12 16:08:19] DEBUG[23508][C-00000000] chan_sip.c: Processing session-level SDP s=Talk... UNSUPPORTED OR FAILED. [May 12 16:08:19] DEBUG[23508][C-00000000] netsock2.c: Splitting '192.168.1.140' into... [May 12 16:08:19] DEBUG[23508][C-00000000] netsock2.c: ...host '192.168.1.140' and port ''. [May 12 16:08:19] DEBUG[23508][C-00000000] chan_sip.c: Processing session-level SDP c=IN IP4 192.168.1.140... OK. [May 12 16:08:19] DEBUG[23508][C-00000000] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [May 12 16:08:19] DEBUG[23508][C-00000000] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7f06517e1180 [May 12 16:08:19] DEBUG[23508][C-00000000] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7f06517e1180 [May 12 16:08:19] DEBUG[23508][C-00000000] rtp_engine.c: Setting tx payload type 101 based on m type on 0x7f06517e1180 [May 12 16:08:19] DEBUG[23508][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [May 12 16:08:19] DEBUG[23508][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [May 12 16:08:19] DEBUG[23508][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [May 12 16:08:19] DEBUG[23508][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-11... UNSUPPORTED OR FAILED. [May 12 16:08:19] DEBUG[23508][C-00000000] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x1ecd848' [May 12 16:08:19] DEBUG[23508][C-00000000] rtp_engine.c: Copying payload 0 (0x1bea8a0) from 0x7f06517e1180 to 0x1ecda10 [May 12 16:08:19] DEBUG[23508][C-00000000] rtp_engine.c: Copying payload 8 (0x1ee7050) from 0x7f06517e1180 to 0x1ecda10 [May 12 16:08:19] DEBUG[23508][C-00000000] rtp_engine.c: Copying payload 101 (0x1bb3640) from 0x7f06517e1180 to 0x1ecda10 [May 12 16:08:19] DEBUG[23508][C-00000000] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x1ecd848' [May 12 16:08:19] DEBUG[23508][C-00000000] chan_sip.c: We're settling with these formats: (ulaw|alaw) [May 12 16:08:19] DEBUG[23508][C-00000000] chan_sip.c: Checking SIP call limits for device 100 [May 12 16:08:19] DEBUG[23508][C-00000000] chan_sip.c: Updating call counter for incoming call [May 12 16:08:19] DEBUG[23508][C-00000000] netsock2.c: Splitting '192.168.1.141' into... [May 12 16:08:19] DEBUG[23508][C-00000000] netsock2.c: ...host '192.168.1.141' and port ''. [May 12 16:08:19] DEBUG[23508][C-00000000] netsock2.c: Splitting '192.168.1.141' into... [May 12 16:08:19] DEBUG[23508][C-00000000] netsock2.c: ...host '192.168.1.141' and port ''. [May 12 16:08:19] DEBUG[23508][C-00000000] chan_sip.c: *** Our native formats are (ulaw) [May 12 16:08:19] DEBUG[23508][C-00000000] chan_sip.c: *** Joint capabilities are (ulaw|alaw) [May 12 16:08:19] DEBUG[23508][C-00000000] chan_sip.c: *** Our capabilities are (ulaw|alaw|gsm|h263) [May 12 16:08:19] DEBUG[23508][C-00000000] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw [May 12 16:08:19] DEBUG[23508][C-00000000] chan_sip.c: This channel will not be able to handle video. [May 12 16:08:19] DEBUG[23508][C-00000000] chan_sip.c: SIP/100-00000000: New call is still down.... Trying... [May 12 16:08:19] DEBUG[23508][C-00000000] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 192.168.1.140:5060 [May 12 16:08:19] DEBUG[23474] devicestate.c: No provider found, checking channel drivers for SIP - 100 [May 12 16:08:19] DEBUG[23474] chan_sip.c: Checking device state for peer 100 [May 12 16:08:19] DEBUG[23474] devicestate.c: Changing state for SIP/100 - state 1 (Not in use) [May 12 16:08:19] DEBUG[23524] app_queue.c: Device 'SIP/100' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [May 12 16:08:19] DEBUG[24011][C-00000000] pbx.c: Launching 'Stasis' [May 12 16:08:19] VERBOSE[24011][C-00000000] pbx.c: Executing [3000@default:1] Stasis("SIP/100-00000000", "test-ari") in new stack [May 12 16:08:19] DEBUG[24011][C-00000000] stasis/app.c: Channel '1463062099.0' is 1 interested in test-ari [May 12 16:08:19] DEBUG[24010] ari/ari_websockets.c: Examining ARI event (length 385): {"application":"test-ari","type":"StasisStart","timestamp":"2016-05-12T16:08:19.341+0200","args":[],"channel":{"id":"1463062099.0","name":"SIP/100-00000000","connected":{"name":"","number":""},"state":"Ring","caller":{"name":"","number":"100"},"accountcode":"","dialplan":{"priority":1,"context":"default","exten":"3000"},"creationtime":"2016-05-12T16:08:19.340+0200","language":"en"}} [May 12 16:08:19] DEBUG[24010] res_http_websocket.c: Writing websocket string of length 385 [May 12 16:08:19] DEBUG[24010] res_http_websocket.c: Writing websocket text frame, length 385 [May 12 16:08:19] DEBUG[24012] http.c: HTTP opening session. Top level [May 12 16:08:19] DEBUG[24012] http.c: HTTP Request URI is /ari/channels/1463062099.0/answer [May 12 16:08:19] DEBUG[24012] http.c: match request [ari/channels/1463062099.0/answer] with handler [httpstatus] len 10 [May 12 16:08:19] DEBUG[24012] http.c: match request [ari/channels/1463062099.0/answer] with handler [phoneprov] len 9 [May 12 16:08:19] DEBUG[24012] http.c: match request [ari/channels/1463062099.0/answer] with handler [static] len 6 [May 12 16:08:19] DEBUG[24012] http.c: match request [ari/channels/1463062099.0/answer] with handler [ari] len 3 [May 12 16:08:19] DEBUG[24012] http.c: Match made with [ari] [May 12 16:08:19] DEBUG[24012] res_ari.c: Finding handler for channels [May 12 16:08:19] DEBUG[24012] res_ari.c: Checking bridges [May 12 16:08:19] DEBUG[24012] res_ari.c: Checking endpoints [May 12 16:08:19] DEBUG[24012] res_ari.c: Checking channels [May 12 16:08:19] DEBUG[24012] res_ari.c: Got it! [May 12 16:08:19] DEBUG[24012] res_ari.c: Finding handler for 1463062099.0 [May 12 16:08:19] DEBUG[24012] res_ari.c: Checking channelId [May 12 16:08:19] DEBUG[24012] res_ari.c: Got it! [May 12 16:08:19] DEBUG[24012] res_ari.c: Finding handler for answer [May 12 16:08:19] DEBUG[24012] res_ari.c: Checking continue [May 12 16:08:19] DEBUG[24012] res_ari.c: Checking redirect [May 12 16:08:19] DEBUG[24012] res_ari.c: Checking answer [May 12 16:08:19] DEBUG[24012] res_ari.c: Got it! [May 12 16:08:19] DEBUG[24012] res_stasis_answer.c: 1463062099.0: Sending answer command [May 12 16:08:19] DEBUG[24011][C-00000000] res_stasis_answer.c: 1463062099.0: Answering [May 12 16:08:19] DEBUG[24011][C-00000000] chan_sip.c: SIP answering channel: SIP/100-00000000 [May 12 16:08:19] DEBUG[24011][C-00000000] res_rtp_asterisk.c: Setting the marker bit due to a source update [May 12 16:08:19] DEBUG[23474] devicestate.c: No provider found, checking channel drivers for SIP - 100 [May 12 16:08:19] DEBUG[23474] chan_sip.c: Checking device state for peer 100 [May 12 16:08:19] DEBUG[23474] devicestate.c: Changing state for SIP/100 - state 1 (Not in use) [May 12 16:08:19] DEBUG[24011][C-00000000] chan_sip.c: ** Our capability: (ulaw|alaw) Video flag: True Text flag: True [May 12 16:08:19] DEBUG[24011][C-00000000] chan_sip.c: ** Our prefcodec: (nothing) [May 12 16:08:19] DEBUG[24011][C-00000000] chan_sip.c: -- Done with adding codecs to SDP [May 12 16:08:19] DEBUG[24011][C-00000000] chan_sip.c: Setting framing on incoming call: 0 [May 12 16:08:19] DEBUG[24011][C-00000000] chan_sip.c: Done building SDP. Settling with this capability: (ulaw|alaw) [May 12 16:08:19] DEBUG[24011][C-00000000] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.1.140:5060 [May 12 16:08:19] DEBUG[24010] ari/ari_websockets.c: Examining ARI event (length 380): {"application":"test-ari","type":"ChannelStateChange","timestamp":"2016-05-12T16:08:19.542+0200","channel":{"id":"1463062099.0","name":"SIP/100-00000000","connected":{"name":"","number":""},"state":"Up","caller":{"name":"","number":"100"},"accountcode":"","dialplan":{"priority":1,"context":"default","exten":"3000"},"creationtime":"2016-05-12T16:08:19.340+0200","language":"en"}} [May 12 16:08:19] DEBUG[24010] res_http_websocket.c: Writing websocket string of length 380 [May 12 16:08:19] DEBUG[24010] res_http_websocket.c: Writing websocket text frame, length 380 [May 12 16:08:19] DEBUG[24012] res_ari.c: Examining ARI response: 204 No Content [May 12 16:08:19] DEBUG[24012] http.c: HTTP discarding unused request body [May 12 16:08:19] DEBUG[24012] http.c: HTTP keeping session open. status_code:204 [May 12 16:08:19] DEBUG[24012] http.c: HTTP idle timeout or peer closed connection. [May 12 16:08:19] DEBUG[24012] http.c: HTTP closing session. Top level [May 12 16:08:19] DEBUG[24013] http.c: HTTP opening session. Top level [May 12 16:08:19] DEBUG[24013] http.c: HTTP Request URI is /ari/bridges?bridgeId=d594e197-eda0-46f6-bca6-53e69200e8d0 [May 12 16:08:19] DEBUG[24013] http.c: match request [ari/bridges] with handler [httpstatus] len 10 [May 12 16:08:19] DEBUG[24013] http.c: match request [ari/bridges] with handler [phoneprov] len 9 [May 12 16:08:19] DEBUG[24013] http.c: match request [ari/bridges] with handler [static] len 6 [May 12 16:08:19] DEBUG[24013] http.c: match request [ari/bridges] with handler [ari] len 3 [May 12 16:08:19] DEBUG[24013] http.c: Match made with [ari] [May 12 16:08:19] DEBUG[24013] res_ari.c: Finding handler for bridges [May 12 16:08:19] DEBUG[24013] res_ari.c: Checking bridges [May 12 16:08:19] DEBUG[24013] res_ari.c: Got it! [May 12 16:08:19] DEBUG[24013] bridge_native_rtp.c: Bridge 'd594e197-eda0-46f6-bca6-53e69200e8d0' can not use native RTP bridge as two channels are required [May 12 16:08:19] DEBUG[24013] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [May 12 16:08:19] DEBUG[24013] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [May 12 16:08:19] DEBUG[24013] bridge.c: Chose bridge technology simple_bridge [May 12 16:08:19] DEBUG[24013] bridge.c: Bridge d594e197-eda0-46f6-bca6-53e69200e8d0: calling simple_bridge technology constructor [May 12 16:08:19] DEBUG[24013] bridge.c: Bridge d594e197-eda0-46f6-bca6-53e69200e8d0: calling simple_bridge technology start [May 12 16:08:19] DEBUG[24013] res_ari.c: Examining ARI response: 200 OK Content-type: application/json {"channels":[],"creator":"Stasis","id":"d594e197-eda0-46f6-bca6-53e69200e8d0","name":"","technology":"simple_bridge","bridge_type":"mixing","bridge_class":"stasis"} [May 12 16:08:19] DEBUG[24013] http.c: HTTP discarding unused request body [May 12 16:08:19] DEBUG[24013] http.c: HTTP keeping session open. status_code:200 [May 12 16:08:19] DEBUG[24013] http.c: HTTP idle timeout or peer closed connection. [May 12 16:08:19] DEBUG[24013] http.c: HTTP closing session. Top level [May 12 16:08:19] DEBUG[24014] http.c: HTTP opening session. Top level [May 12 16:08:19] DEBUG[24014] http.c: HTTP Request URI is /ari/bridges/d594e197-eda0-46f6-bca6-53e69200e8d0/addChannel?channel=1463062099.0 [May 12 16:08:19] DEBUG[24014] http.c: match request [ari/bridges/d594e197-eda0-46f6-bca6-53e69200e8d0/addChannel] with handler [httpstatus] len 10 [May 12 16:08:19] DEBUG[24014] http.c: match request [ari/bridges/d594e197-eda0-46f6-bca6-53e69200e8d0/addChannel] with handler [phoneprov] len 9 [May 12 16:08:19] DEBUG[24014] http.c: match request [ari/bridges/d594e197-eda0-46f6-bca6-53e69200e8d0/addChannel] with handler [static] len 6 [May 12 16:08:19] DEBUG[24014] http.c: match request [ari/bridges/d594e197-eda0-46f6-bca6-53e69200e8d0/addChannel] with handler [ari] len 3 [May 12 16:08:19] DEBUG[24014] http.c: Match made with [ari] [May 12 16:08:19] DEBUG[24014] res_ari.c: Finding handler for bridges [May 12 16:08:19] DEBUG[24014] res_ari.c: Checking bridges [May 12 16:08:19] DEBUG[24014] res_ari.c: Got it! [May 12 16:08:19] DEBUG[24014] res_ari.c: Finding handler for d594e197-eda0-46f6-bca6-53e69200e8d0 [May 12 16:08:19] DEBUG[24014] res_ari.c: Checking bridgeId [May 12 16:08:19] DEBUG[24014] res_ari.c: Got it! [May 12 16:08:19] DEBUG[24014] res_ari.c: Finding handler for addChannel [May 12 16:08:19] DEBUG[24014] res_ari.c: Checking addChannel [May 12 16:08:19] DEBUG[24014] res_ari.c: Got it! [May 12 16:08:19] DEBUG[24014] bridge_roles.c: Roles did not exist on channel SIP/100-00000000 [May 12 16:08:19] DEBUG[24014] stasis/control.c: 1463062099.0: Sending channel add_to_bridge command [May 12 16:08:19] DEBUG[23508] chan_sip.c: = Looking for Call ID: 663848766 (Checking From) --From tag 1790999805 --To-tag as5903b188 [May 12 16:08:19] DEBUG[23508][C-00000000] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [May 12 16:08:19] DEBUG[23508][C-00000000] chan_sip.c: Stopping retransmission on '663848766' of Response 21: Match Found [May 12 16:08:19] DEBUG[24011][C-00000000] stasis/control.c: 1463062099.0: Adding to bridge d594e197-eda0-46f6-bca6-53e69200e8d0 [May 12 16:08:19] DEBUG[24011][C-00000000] stasis/app.c: Bridge 'd594e197-eda0-46f6-bca6-53e69200e8d0' is 1 interested in test-ari [May 12 16:08:19] DEBUG[24015][C-00000000] bridge_channel.c: Bridge d594e197-eda0-46f6-bca6-53e69200e8d0: 0x7f068c002ce8(SIP/100-00000000) is joining [May 12 16:08:19] DEBUG[24015][C-00000000] bridge_channel.c: Bridge d594e197-eda0-46f6-bca6-53e69200e8d0: pushing 0x7f068c002ce8(SIP/100-00000000) [May 12 16:08:19] VERBOSE[24015][C-00000000] bridge_channel.c: Channel SIP/100-00000000 joined 'simple_bridge' stasis-bridge [May 12 16:08:19] DEBUG[24015][C-00000000] bridge_native_rtp.c: Bridge 'd594e197-eda0-46f6-bca6-53e69200e8d0' can not use native RTP bridge as two channels are required [May 12 16:08:19] DEBUG[24015][C-00000000] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [May 12 16:08:19] DEBUG[24015][C-00000000] bridge.c: Bridge technology softmix does not have any capabilities we want. [May 12 16:08:19] DEBUG[24015][C-00000000] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [May 12 16:08:19] DEBUG[24015][C-00000000] bridge.c: Chose bridge technology simple_bridge [May 12 16:08:19] DEBUG[24015][C-00000000] bridge.c: Bridge d594e197-eda0-46f6-bca6-53e69200e8d0 is already using the new technology. [May 12 16:08:19] DEBUG[24015][C-00000000] bridge.c: Bridge d594e197-eda0-46f6-bca6-53e69200e8d0: 0x7f068c002ce8(SIP/100-00000000) is joining simple_bridge technology [May 12 16:08:19] DEBUG[24015][C-00000000] res_rtp_asterisk.c: Not changing SSRC since we haven't sent any RTP yet [May 12 16:08:19] DEBUG[24010] ari/ari_websockets.c: Examining ARI event (length 570): {"application":"test-ari","type":"ChannelEnteredBridge","bridge":{"channels":["1463062099.0"],"creator":"Stasis","id":"d594e197-eda0-46f6-bca6-53e69200e8d0","name":"","technology":"simple_bridge","bridge_type":"mixing","bridge_class":"stasis"},"timestamp":"2016-05-12T16:08:19.561+0200","channel":{"id":"1463062099.0","name":"SIP/100-00000000","connected":{"name":"","number":""},"state":"Up","caller":{"name":"","number":"100"},"accountcode":"","dialplan":{"priority":1,"context":"default","exten":"3000"},"creationtime":"2016-05-12T16:08:19.340+0200","language":"en"}} [May 12 16:08:19] DEBUG[24010] res_http_websocket.c: Writing websocket string of length 570 [May 12 16:08:19] DEBUG[24010] res_http_websocket.c: Writing websocket text frame, length 570 [May 12 16:08:19] DEBUG[24011][C-00000000] stasis/app.c: App 'test-ari' not subscribed to bridge '__AST_BRIDGE_ALL_TOPIC' [May 12 16:08:19] DEBUG[24011][C-00000000] stasis/app.c: Bridge 'd594e197-eda0-46f6-bca6-53e69200e8d0' is 2 interested in test-ari [May 12 16:08:19] DEBUG[24014] res_ari.c: Examining ARI response: 204 No Content [May 12 16:08:19] DEBUG[24014] http.c: HTTP discarding unused request body [May 12 16:08:19] DEBUG[24014] http.c: HTTP keeping session open. status_code:204 [May 12 16:08:19] DEBUG[24014] http.c: HTTP idle timeout or peer closed connection. [May 12 16:08:19] DEBUG[24014] http.c: HTTP closing session. Top level [May 12 16:08:19] DEBUG[24015][C-00000000] res_rtp_asterisk.c: 0x1f4c9b0 -- Probation learning mode pass with source address 192.168.1.140:7078 [May 12 16:08:21] DEBUG[24016] http.c: HTTP opening session. Top level [May 12 16:08:21] DEBUG[24016] http.c: HTTP Request URI is /ari/bridges?bridgeId=e4c63a4c-0c35-4f9b-a2bd-a0608b2a2601 [May 12 16:08:21] DEBUG[24016] http.c: match request [ari/bridges] with handler [httpstatus] len 10 [May 12 16:08:21] DEBUG[24016] http.c: match request [ari/bridges] with handler [phoneprov] len 9 [May 12 16:08:21] DEBUG[24016] http.c: match request [ari/bridges] with handler [static] len 6 [May 12 16:08:21] DEBUG[24016] http.c: match request [ari/bridges] with handler [ari] len 3 [May 12 16:08:21] DEBUG[24016] http.c: Match made with [ari] [May 12 16:08:21] DEBUG[24016] res_ari.c: Finding handler for bridges [May 12 16:08:21] DEBUG[24016] res_ari.c: Checking bridges [May 12 16:08:21] DEBUG[24016] res_ari.c: Got it! [May 12 16:08:21] DEBUG[24016] bridge_native_rtp.c: Bridge 'e4c63a4c-0c35-4f9b-a2bd-a0608b2a2601' can not use native RTP bridge as two channels are required [May 12 16:08:21] DEBUG[24016] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [May 12 16:08:21] DEBUG[24016] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [May 12 16:08:21] DEBUG[24016] bridge.c: Chose bridge technology simple_bridge [May 12 16:08:21] DEBUG[24016] bridge.c: Bridge e4c63a4c-0c35-4f9b-a2bd-a0608b2a2601: calling simple_bridge technology constructor [May 12 16:08:21] DEBUG[24016] bridge.c: Bridge e4c63a4c-0c35-4f9b-a2bd-a0608b2a2601: calling simple_bridge technology start [May 12 16:08:21] DEBUG[24016] res_ari.c: Examining ARI response: 200 OK Content-type: application/json {"channels":[],"creator":"Stasis","id":"e4c63a4c-0c35-4f9b-a2bd-a0608b2a2601","name":"","technology":"simple_bridge","bridge_type":"mixing","bridge_class":"stasis"} [May 12 16:08:21] DEBUG[24016] http.c: HTTP discarding unused request body [May 12 16:08:21] DEBUG[24016] http.c: HTTP keeping session open. status_code:200 [May 12 16:08:21] DEBUG[24016] http.c: HTTP idle timeout or peer closed connection. [May 12 16:08:21] DEBUG[24016] http.c: HTTP closing session. Top level [May 12 16:08:21] DEBUG[24017] http.c: HTTP opening session. Top level [May 12 16:08:21] DEBUG[24017] http.c: HTTP Request URI is /ari/bridges/e4c63a4c-0c35-4f9b-a2bd-a0608b2a2601/addChannel?channel=1463062099.0 [May 12 16:08:21] DEBUG[24017] http.c: match request [ari/bridges/e4c63a4c-0c35-4f9b-a2bd-a0608b2a2601/addChannel] with handler [httpstatus] len 10 [May 12 16:08:21] DEBUG[24017] http.c: match request [ari/bridges/e4c63a4c-0c35-4f9b-a2bd-a0608b2a2601/addChannel] with handler [phoneprov] len 9 [May 12 16:08:21] DEBUG[24017] http.c: match request [ari/bridges/e4c63a4c-0c35-4f9b-a2bd-a0608b2a2601/addChannel] with handler [static] len 6 [May 12 16:08:21] DEBUG[24017] http.c: match request [ari/bridges/e4c63a4c-0c35-4f9b-a2bd-a0608b2a2601/addChannel] with handler [ari] len 3 [May 12 16:08:21] DEBUG[24017] http.c: Match made with [ari] [May 12 16:08:21] DEBUG[24017] res_ari.c: Finding handler for bridges [May 12 16:08:21] DEBUG[24017] res_ari.c: Checking bridges [May 12 16:08:21] DEBUG[24017] res_ari.c: Got it! [May 12 16:08:21] DEBUG[24017] res_ari.c: Finding handler for e4c63a4c-0c35-4f9b-a2bd-a0608b2a2601 [May 12 16:08:21] DEBUG[24017] res_ari.c: Checking bridgeId [May 12 16:08:21] DEBUG[24017] res_ari.c: Got it! [May 12 16:08:21] DEBUG[24017] res_ari.c: Finding handler for addChannel [May 12 16:08:21] DEBUG[24017] res_ari.c: Checking addChannel [May 12 16:08:21] DEBUG[24017] res_ari.c: Got it! [May 12 16:08:21] DEBUG[24017] bridge_roles.c: Roles did not exist on channel SIP/100-00000000 [May 12 16:08:21] DEBUG[24017] stasis/control.c: 1463062099.0: Sending channel add_to_bridge command [May 12 16:08:21] DEBUG[24011][C-00000000] stasis/control.c: 1463062099.0: Adding to bridge e4c63a4c-0c35-4f9b-a2bd-a0608b2a2601 [May 12 16:08:21] DEBUG[24011][C-00000000] bridge_channel.c: Setting 0x7f068c002ce8(SIP/100-00000000) state from:0 to:2 [May 12 16:08:21] DEBUG[24011][C-00000000] bridge.c: Waiting for 0x7f068c002ce8(SIP/100-00000000) bridge thread to die. [May 12 16:08:21] DEBUG[24015][C-00000000] bridge_channel.c: Bridge d594e197-eda0-46f6-bca6-53e69200e8d0: pulling 0x7f068c002ce8(SIP/100-00000000) [May 12 16:08:21] VERBOSE[24015][C-00000000] bridge_channel.c: Channel SIP/100-00000000 left 'simple_bridge' stasis-bridge [May 12 16:08:21] DEBUG[24015][C-00000000] bridge_channel.c: Bridge d594e197-eda0-46f6-bca6-53e69200e8d0: 0x7f068c002ce8(SIP/100-00000000) is leaving simple_bridge technology [May 12 16:08:21] DEBUG[24015][C-00000000] bridge_native_rtp.c: Bridge 'd594e197-eda0-46f6-bca6-53e69200e8d0' can not use native RTP bridge as two channels are required [May 12 16:08:21] DEBUG[24015][C-00000000] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [May 12 16:08:21] DEBUG[24015][C-00000000] bridge.c: Bridge technology softmix does not have any capabilities we want. [May 12 16:08:21] DEBUG[24015][C-00000000] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [May 12 16:08:21] DEBUG[24015][C-00000000] bridge.c: Chose bridge technology simple_bridge [May 12 16:08:21] DEBUG[24015][C-00000000] bridge.c: Bridge d594e197-eda0-46f6-bca6-53e69200e8d0 is already using the new technology. [May 12 16:08:21] DEBUG[24015][C-00000000] res_rtp_asterisk.c: Not changing SSRC since we haven't sent any RTP yet [May 12 16:08:21] DEBUG[24015][C-00000000] stasis/control.c: 1463062099.0, d594e197-eda0-46f6-bca6-53e69200e8d0: Channel leaving bridge [May 12 16:08:21] DEBUG[24015][C-00000000] stasis/app.c: bridge 'd594e197-eda0-46f6-bca6-53e69200e8d0': is 1 interested in test-ari [May 12 16:08:21] DEBUG[24015][C-00000000] stasis/control.c: reason: Channel was departed from bridge [May 12 16:08:21] DEBUG[23476] cdr.c: Finalized CDR for SIP/100-00000000 - start 1463062099.340362 answer 1463062099.542471 end 1463062101.571159 dispo ANSWERED [May 12 16:08:21] DEBUG[24011][C-00000000] stasis/app.c: Bridge 'e4c63a4c-0c35-4f9b-a2bd-a0608b2a2601' is 1 interested in test-ari [May 12 16:08:21] DEBUG[24010] ari/ari_websockets.c: Examining ARI event (length 553): {"application":"test-ari","type":"ChannelLeftBridge","bridge":{"channels":[],"creator":"Stasis","id":"d594e197-eda0-46f6-bca6-53e69200e8d0","name":"","technology":"simple_bridge","bridge_type":"mixing","bridge_class":"stasis"},"timestamp":"2016-05-12T16:08:21.570+0200","channel":{"id":"1463062099.0","name":"SIP/100-00000000","connected":{"name":"","number":""},"state":"Up","caller":{"name":"","number":"100"},"accountcode":"","dialplan":{"priority":1,"context":"default","exten":"3000"},"creationtime":"2016-05-12T16:08:19.340+0200","language":"en"}} [May 12 16:08:21] DEBUG[24010] res_http_websocket.c: Writing websocket string of length 553 [May 12 16:08:21] DEBUG[24010] res_http_websocket.c: Writing websocket text frame, length 553 [May 12 16:08:21] DEBUG[24018][C-00000000] bridge_channel.c: Bridge e4c63a4c-0c35-4f9b-a2bd-a0608b2a2601: 0x7f068c000d28(SIP/100-00000000) is joining [May 12 16:08:21] DEBUG[24018][C-00000000] bridge_channel.c: Bridge e4c63a4c-0c35-4f9b-a2bd-a0608b2a2601: pushing 0x7f068c000d28(SIP/100-00000000) [May 12 16:08:21] VERBOSE[24018][C-00000000] bridge_channel.c: Channel SIP/100-00000000 joined 'simple_bridge' stasis-bridge [May 12 16:08:21] DEBUG[24018][C-00000000] bridge_native_rtp.c: Bridge 'e4c63a4c-0c35-4f9b-a2bd-a0608b2a2601' can not use native RTP bridge as two channels are required [May 12 16:08:21] DEBUG[24018][C-00000000] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [May 12 16:08:21] DEBUG[24018][C-00000000] bridge.c: Bridge technology softmix does not have any capabilities we want. [May 12 16:08:21] DEBUG[24018][C-00000000] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [May 12 16:08:21] DEBUG[24018][C-00000000] bridge.c: Chose bridge technology simple_bridge [May 12 16:08:21] DEBUG[24018][C-00000000] bridge.c: Bridge e4c63a4c-0c35-4f9b-a2bd-a0608b2a2601 is already using the new technology. [May 12 16:08:21] DEBUG[24018][C-00000000] bridge.c: Bridge e4c63a4c-0c35-4f9b-a2bd-a0608b2a2601: 0x7f068c000d28(SIP/100-00000000) is joining simple_bridge technology [May 12 16:08:21] DEBUG[24018][C-00000000] res_rtp_asterisk.c: Not changing SSRC since we haven't sent any RTP yet [May 12 16:08:21] DEBUG[24010] ari/ari_websockets.c: Examining ARI event (length 570): {"application":"test-ari","type":"ChannelEnteredBridge","bridge":{"channels":["1463062099.0"],"creator":"Stasis","id":"e4c63a4c-0c35-4f9b-a2bd-a0608b2a2601","name":"","technology":"simple_bridge","bridge_type":"mixing","bridge_class":"stasis"},"timestamp":"2016-05-12T16:08:21.573+0200","channel":{"id":"1463062099.0","name":"SIP/100-00000000","connected":{"name":"","number":""},"state":"Up","caller":{"name":"","number":"100"},"accountcode":"","dialplan":{"priority":1,"context":"default","exten":"3000"},"creationtime":"2016-05-12T16:08:19.340+0200","language":"en"}} [May 12 16:08:21] DEBUG[24010] res_http_websocket.c: Writing websocket string of length 570 [May 12 16:08:21] DEBUG[24010] res_http_websocket.c: Writing websocket text frame, length 570 [May 12 16:08:21] DEBUG[24011][C-00000000] stasis/control.c: 1463062099.0: Channel is no longer in departable state [May 12 16:08:21] DEBUG[24011][C-00000000] stasis/app.c: bridge 'd594e197-eda0-46f6-bca6-53e69200e8d0': is 0 interested in test-ari [May 12 16:08:21] DEBUG[24011][C-00000000] stasis/app.c: bridge 'd594e197-eda0-46f6-bca6-53e69200e8d0' unsubscribed from test-ari [May 12 16:08:21] DEBUG[24011][C-00000000] stasis/app.c: Bridge 'e4c63a4c-0c35-4f9b-a2bd-a0608b2a2601' is 2 interested in test-ari [May 12 16:08:21] DEBUG[24017] res_ari.c: Examining ARI response: 204 No Content [May 12 16:08:21] DEBUG[24017] http.c: HTTP discarding unused request body [May 12 16:08:21] DEBUG[24017] http.c: HTTP keeping session open. status_code:204 [May 12 16:08:21] DEBUG[24017] http.c: HTTP idle timeout or peer closed connection. [May 12 16:08:21] DEBUG[24017] http.c: HTTP closing session. Top level [May 12 16:08:21] DEBUG[24019] http.c: HTTP opening session. Top level [May 12 16:08:21] DEBUG[24019] http.c: HTTP Request URI is /ari/bridges/d594e197-eda0-46f6-bca6-53e69200e8d0 [May 12 16:08:21] DEBUG[24019] http.c: match request [ari/bridges/d594e197-eda0-46f6-bca6-53e69200e8d0] with handler [httpstatus] len 10 [May 12 16:08:21] DEBUG[24019] http.c: match request [ari/bridges/d594e197-eda0-46f6-bca6-53e69200e8d0] with handler [phoneprov] len 9 [May 12 16:08:21] DEBUG[24019] http.c: match request [ari/bridges/d594e197-eda0-46f6-bca6-53e69200e8d0] with handler [static] len 6 [May 12 16:08:21] DEBUG[24019] http.c: match request [ari/bridges/d594e197-eda0-46f6-bca6-53e69200e8d0] with handler [ari] len 3 [May 12 16:08:21] DEBUG[24019] http.c: Match made with [ari] [May 12 16:08:21] DEBUG[24019] res_ari.c: Finding handler for bridges [May 12 16:08:21] DEBUG[24019] res_ari.c: Checking bridges [May 12 16:08:21] DEBUG[24019] res_ari.c: Got it! [May 12 16:08:21] DEBUG[24019] res_ari.c: Finding handler for d594e197-eda0-46f6-bca6-53e69200e8d0 [May 12 16:08:21] DEBUG[24019] res_ari.c: Checking bridgeId [May 12 16:08:21] DEBUG[24019] res_ari.c: Got it! [May 12 16:08:21] DEBUG[24019] bridge.c: Bridge d594e197-eda0-46f6-bca6-53e69200e8d0: telling all channels to leave the party [May 12 16:08:21] DEBUG[24019] bridge.c: Bridge d594e197-eda0-46f6-bca6-53e69200e8d0: dissolving bridge with cause 16(Normal Clearing) [May 12 16:08:21] DEBUG[24019] bridge.c: Bridge d594e197-eda0-46f6-bca6-53e69200e8d0: queueing action type:13 sub:1001 [May 12 16:08:21] DEBUG[24019] res_ari.c: Examining ARI response: 204 No Content [May 12 16:08:21] DEBUG[24019] http.c: HTTP discarding unused request body [May 12 16:08:21] DEBUG[24019] http.c: HTTP keeping session open. status_code:204 [May 12 16:08:21] DEBUG[24019] http.c: HTTP idle timeout or peer closed connection. [May 12 16:08:21] DEBUG[24019] http.c: HTTP closing session. Top level [May 12 16:08:22] DEBUG[24018][C-00000000] res_rtp_asterisk.c: Got RTCP report of 80 bytes [May 12 16:08:22] DEBUG[24018][C-00000000] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [May 12 16:08:22] DEBUG[24018][C-00000000] netsock2.c: Splitting 'vm-centos-jean' into... [May 12 16:08:22] DEBUG[24018][C-00000000] netsock2.c: ...host 'vm-centos-jean' and port ''. [May 12 16:08:22] DEBUG[24018][C-00000000] acl.c: Multiple addresses. Using the first only [May 12 16:08:22] DEBUG[24018][C-00000000] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [May 12 16:08:22] DEBUG[24018][C-00000000] acl.c: Attached to given IP address [May 12 16:08:22] DEBUG[23514] netsock2.c: Splitting '192.168.1.140:7079' into... [May 12 16:08:22] DEBUG[23514] netsock2.c: ...host '192.168.1.140' and port '7079'. [May 12 16:08:22] DEBUG[23514] netsock2.c: Splitting '[::1]:0' into... [May 12 16:08:22] DEBUG[23514] netsock2.c: ...host '::1' and port '0'. [May 12 16:08:22] NOTICE[23486] res_hep.c: Unable to send packet: Address Family mismatch between source/destination [May 12 16:08:24] DEBUG[24018][C-00000000] res_rtp_asterisk.c: Got RTCP report of 80 bytes [May 12 16:08:24] DEBUG[24018][C-00000000] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [May 12 16:08:24] DEBUG[24018][C-00000000] netsock2.c: Splitting 'vm-centos-jean' into... [May 12 16:08:24] DEBUG[24018][C-00000000] netsock2.c: ...host 'vm-centos-jean' and port ''. [May 12 16:08:24] DEBUG[24018][C-00000000] acl.c: Multiple addresses. Using the first only [May 12 16:08:24] DEBUG[24018][C-00000000] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [May 12 16:08:24] DEBUG[24018][C-00000000] acl.c: Attached to given IP address [May 12 16:08:24] DEBUG[23514] netsock2.c: Splitting '192.168.1.140:7079' into... [May 12 16:08:24] DEBUG[23514] netsock2.c: ...host '192.168.1.140' and port '7079'. [May 12 16:08:24] DEBUG[23514] netsock2.c: Splitting '[::1]:0' into... [May 12 16:08:24] DEBUG[23514] netsock2.c: ...host '::1' and port '0'. [May 12 16:08:24] NOTICE[23486] res_hep.c: Unable to send packet: Address Family mismatch between source/destination [May 12 16:08:24] DEBUG[23464] threadpool.c: Worker thread idle timeout reached. Dying. [May 12 16:08:24] DEBUG[23466] threadpool.c: Worker thread idle timeout reached. Dying. [May 12 16:08:24] DEBUG[23469] threadpool.c: Worker thread idle timeout reached. Dying. [May 12 16:08:24] DEBUG[23462] threadpool.c: Destroying worker thread 1 [May 12 16:08:24] DEBUG[23462] threadpool.c: Destroying worker thread 2 [May 12 16:08:24] DEBUG[23462] threadpool.c: Destroying worker thread 4 [May 12 16:08:24] DEBUG[23467] threadpool.c: Worker thread idle timeout reached. Dying. [May 12 16:08:24] DEBUG[23462] threadpool.c: Destroying worker thread 3 [May 12 16:08:24] DEBUG[23508] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [May 12 16:08:24] DEBUG[23508] netsock2.c: Splitting 'vm-centos-jean' into... [May 12 16:08:24] DEBUG[23508] netsock2.c: ...host 'vm-centos-jean' and port ''. [May 12 16:08:24] DEBUG[23508] acl.c: Multiple addresses. Using the first only [May 12 16:08:24] DEBUG[23508] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [May 12 16:08:24] DEBUG[23508] acl.c: Attached to given IP address [May 12 16:08:24] DEBUG[23514] netsock2.c: Splitting '[::1]:0' into... [May 12 16:08:24] DEBUG[23514] netsock2.c: ...host '::1' and port '0'. [May 12 16:08:24] DEBUG[23514] netsock2.c: Splitting '192.168.1.140:7079' into... [May 12 16:08:24] DEBUG[23514] netsock2.c: ...host '192.168.1.140' and port '7079'. [May 12 16:08:24] NOTICE[23486] res_hep.c: Unable to send packet: Address Family mismatch between source/destination [May 12 16:08:27] DEBUG[24018][C-00000000] res_rtp_asterisk.c: Got RTCP report of 80 bytes [May 12 16:08:27] DEBUG[24018][C-00000000] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [May 12 16:08:27] DEBUG[24018][C-00000000] netsock2.c: Splitting 'vm-centos-jean' into... [May 12 16:08:27] DEBUG[24018][C-00000000] netsock2.c: ...host 'vm-centos-jean' and port ''. [May 12 16:08:27] DEBUG[24018][C-00000000] acl.c: Multiple addresses. Using the first only [May 12 16:08:27] DEBUG[24018][C-00000000] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [May 12 16:08:27] DEBUG[24018][C-00000000] acl.c: Attached to given IP address [May 12 16:08:27] DEBUG[23514] netsock2.c: Splitting '192.168.1.140:7079' into... [May 12 16:08:27] DEBUG[23514] netsock2.c: ...host '192.168.1.140' and port '7079'. [May 12 16:08:27] DEBUG[23514] netsock2.c: Splitting '[::1]:0' into... [May 12 16:08:27] DEBUG[23514] netsock2.c: ...host '::1' and port '0'. [May 12 16:08:27] NOTICE[23486] res_hep.c: Unable to send packet: Address Family mismatch between source/destination [May 12 16:08:29] NOTICE[23486] res_hep.c: Unable to send packet: Address Family mismatch between source/destination [May 12 16:08:29] NOTICE[23486] res_hep.c: Unable to send packet: Address Family mismatch between source/destination [May 12 16:08:32] NOTICE[23486] res_hep.c: Unable to send packet: Address Family mismatch between source/destination [May 12 16:08:34] NOTICE[23486] res_hep.c: Unable to send packet: Address Family mismatch between source/destination [May 12 16:08:34] NOTICE[23486] res_hep.c: Unable to send packet: Address Family mismatch between source/destination [May 12 16:08:39] NOTICE[23486] res_hep.c: Unable to send packet: Address Family mismatch between source/destination [May 12 16:08:39] NOTICE[23486] res_hep.c: Unable to send packet: Address Family mismatch between source/destination [May 12 16:08:44] NOTICE[23486] res_hep.c: Unable to send packet: Address Family mismatch between source/destination [May 12 16:08:44] NOTICE[23486] res_hep.c: Unable to send packet: Address Family mismatch between source/destination [May 12 16:08:46] VERBOSE[24018][C-00000000] bridge_channel.c: Channel SIP/100-00000000 left 'simple_bridge' stasis-bridge