[Jun 3 22:06:13] DEBUG[18048] res_pjsip_session.c: Media stream 'audio' handled by audio [Jun 3 22:06:13] DEBUG[18048] res_pjsip_t38.c: Not creating outgoing SDP stream: T.38 not enabled [Jun 3 22:06:13] DEBUG[18048] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [Jun 3 22:06:13] DEBUG[18048] netsock2.c: Splitting '0.0.0.0:5060' into... [Jun 3 22:06:13] DEBUG[18048] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jun 3 22:06:13] DEBUG[18048] netsock2.c: Splitting 'REDACTED:5060' into... [Jun 3 22:06:13] DEBUG[18048] netsock2.c: ...host 'REDACTED' and port '5060'. [Jun 3 22:06:13] DEBUG[18048] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Jun 3 22:06:13] DEBUG[18048] res_pjsip_session.c: The state change pertains to the endpoint 'sip-standard()' [Jun 3 22:06:13] DEBUG[18048] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f429800d618) [Jun 3 22:06:13] DEBUG[18048] res_pjsip_session.c: There is no transaction involved in this state change [Jun 3 22:06:13] DEBUG[18048] res_pjsip_session.c: The current inv state is INCOMING [Jun 3 22:06:13] DEBUG[18048] res_pjsip_session.c: Source of transaction state change is TX_MSG [Jun 3 22:06:13] DEBUG[18048] res_pjsip_session.c: Sending response [Jun 3 22:06:13] DEBUG[18048] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [Jun 3 22:06:13] DEBUG[18048] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jun 3 22:06:13] DEBUG[18048] res_pjsip_session.c: The state change pertains to the endpoint 'sip-standard()' [Jun 3 22:06:13] DEBUG[18048] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f429800d618) [Jun 3 22:06:13] DEBUG[18048] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f429800d618 [Jun 3 22:06:13] DEBUG[18048] res_pjsip_session.c: The current transaction state is Proceeding [Jun 3 22:06:13] DEBUG[18048] res_pjsip_session.c: The transaction state change event is TX_MSG [Jun 3 22:06:13] DEBUG[18048] res_pjsip_session.c: The current inv state is INCOMING [Jun 3 22:06:13] DEBUG[18048] res_pjsip_session.c: Sending response [Jun 3 22:06:13] DEBUG[18048] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [Jun 3 22:06:13] DEBUG[18048] res_pjsip_session.c: Method is INVITE [Jun 3 22:06:13] DEBUG[18048] chan_pjsip.c: Started PBX on new PJSIP channel PJSIP/sip-standard-0000000f [Jun 3 22:06:13] DEBUG[28020] ari/ari_websockets.c: Examining ARI event (length 429): {"application":"switchboard","type":"StasisStart","timestamp":"2016-06-03T22:06:13.789+0000","args":[],"channel":{"id":"i-0a321ef5a9fcf448c-1464991573.68","state":"Ring","name":"PJSIP/sip-standard-0000000f","caller":{"name":"","number":"sip-standard"},"language":"en","connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"default","exten":"0000","priority":3},"creationtime":"2016-06-03T22:06:13.787+0000"}} [Jun 3 22:06:13] DEBUG[28020] res_http_websocket.c: Writing websocket string of length 429 [Jun 3 22:06:13] DEBUG[28020] res_http_websocket.c: Writing websocket text frame, length 429 [Jun 3 22:06:13] DEBUG[28170] http.c: HTTP opening session. Top level [Jun 3 22:06:13] DEBUG[28170] http.c: HTTP Request URI is /ari/channels/i-0a321ef5a9fcf448c-1464991573.68/variable [Jun 3 22:06:13] DEBUG[28170] http.c: match request [ari/channels/i-0a321ef5a9fcf448c-1464991573.68/variable] with handler [httpstatus] len 10 [Jun 3 22:06:13] DEBUG[28170] http.c: match request [ari/channels/i-0a321ef5a9fcf448c-1464991573.68/variable] with handler [static] len 6 [Jun 3 22:06:13] DEBUG[28170] http.c: match request [ari/channels/i-0a321ef5a9fcf448c-1464991573.68/variable] with handler [ari] len 3 [Jun 3 22:06:13] DEBUG[28170] http.c: Match made with [ari] [Jun 3 22:06:13] DEBUG[28170] res_ari.c: Finding handler for channels [Jun 3 22:06:13] DEBUG[28170] res_ari.c: Checking channels [Jun 3 22:06:13] DEBUG[28170] res_ari.c: Got it! [Jun 3 22:06:13] DEBUG[28170] res_ari.c: Finding handler for i-0a321ef5a9fcf448c-1464991573.68 [Jun 3 22:06:13] DEBUG[28170] res_ari.c: Checking channelId [Jun 3 22:06:13] DEBUG[28170] res_ari.c: Got it! [Jun 3 22:06:13] DEBUG[28170] res_ari.c: Finding handler for variable [Jun 3 22:06:13] DEBUG[28170] res_ari.c: Checking continue [Jun 3 22:06:13] DEBUG[28170] res_ari.c: Checking redirect [Jun 3 22:06:13] DEBUG[28170] res_ari.c: Checking answer [Jun 3 22:06:13] DEBUG[28170] res_ari.c: Checking ring [Jun 3 22:06:13] DEBUG[28170] res_ari.c: Checking dtmf [Jun 3 22:06:13] DEBUG[28170] res_ari.c: Checking mute [Jun 3 22:06:13] DEBUG[28170] res_ari.c: Checking hold [Jun 3 22:06:13] DEBUG[28170] res_ari.c: Checking moh [Jun 3 22:06:13] DEBUG[28170] res_ari.c: Checking silence [Jun 3 22:06:13] DEBUG[28170] res_ari.c: Checking play [Jun 3 22:06:13] DEBUG[28170] res_ari.c: Checking record [Jun 3 22:06:13] DEBUG[28170] res_ari.c: Checking variable [Jun 3 22:06:13] DEBUG[28170] res_ari.c: Got it! [Jun 3 22:06:13] DEBUG[28170] http.c: HTTP consuming request body [Jun 3 22:06:13] DEBUG[28170] pbx_variables.c: Result of 'pack' is 'REDACTED STRING' [Jun 3 22:06:13] DEBUG[28170] res_ari.c: Examining ARI response: 200 OK Content-type: application/json {"value":"REDACTED STRING"} [Jun 3 22:06:13] DEBUG[28170] http.c: HTTP keeping session open. status_code:200 [Jun 3 22:06:13] DEBUG[28170] http.c: HTTP idle timeout or peer closed connection. [Jun 3 22:06:13] DEBUG[28170] http.c: HTTP closing session. Top level [Jun 3 22:06:13] DEBUG[28172] http.c: HTTP opening session. Top level [Jun 3 22:06:13] DEBUG[28172] http.c: HTTP Request URI is /ari/events?api_key=REDACTED:RECACTED&app=4-call-6309ed62-29d7-11e6-9c63-defe000026b4-v3 [Jun 3 22:06:13] DEBUG[28172] http.c: match request [ari/events] with handler [httpstatus] len 10 [Jun 3 22:06:13] DEBUG[28172] http.c: match request [ari/events] with handler [static] len 6 [Jun 3 22:06:13] DEBUG[28172] http.c: match request [ari/events] with handler [ari] len 3 [Jun 3 22:06:13] DEBUG[28172] http.c: Match made with [ari] [Jun 3 22:06:13] DEBUG[28172] res_ari.c: Finding handler for events [Jun 3 22:06:13] DEBUG[28172] res_ari.c: Checking channels [Jun 3 22:06:13] DEBUG[28172] res_ari.c: Checking asterisk [Jun 3 22:06:13] DEBUG[28172] res_ari.c: Checking deviceStates [Jun 3 22:06:13] DEBUG[28172] res_ari.c: Checking bridges [Jun 3 22:06:13] DEBUG[28172] res_ari.c: Checking events [Jun 3 22:06:13] DEBUG[28172] res_ari.c: Got it! [Jun 3 22:06:13] DEBUG[28172] ari/resource_events.c: /events WebSocket attempted [Jun 3 22:06:13] VERBOSE[28172] stasis/app.c: Creating Stasis app '4-call-6309ed62-29d7-11e6-9c63-defe000026b4-v3' [Jun 3 22:06:13] VERBOSE[28172] res_http_websocket.c: WebSocket connection from '127.0.0.1:42311' for protocol '' accepted using version '13' [Jun 3 22:06:13] DEBUG[28172] ari/resource_events.c: /events WebSocket connection [Jun 3 22:06:13] VERBOSE[28172] stasis/app.c: Activating Stasis app '4-call-6309ed62-29d7-11e6-9c63-defe000026b4-v3' [Jun 3 22:06:13] DEBUG[28175] http.c: HTTP opening session. Top level [Jun 3 22:06:13] DEBUG[28175] http.c: HTTP Request URI is /ari/channels/i-0a321ef5a9fcf448c-1464991573.68/continue [Jun 3 22:06:13] DEBUG[28175] http.c: match request [ari/channels/i-0a321ef5a9fcf448c-1464991573.68/continue] with handler [httpstatus] len 10 [Jun 3 22:06:13] DEBUG[28175] http.c: match request [ari/channels/i-0a321ef5a9fcf448c-1464991573.68/continue] with handler [static] len 6 [Jun 3 22:06:13] DEBUG[28175] http.c: match request [ari/channels/i-0a321ef5a9fcf448c-1464991573.68/continue] with handler [ari] len 3 [Jun 3 22:06:13] DEBUG[28175] http.c: Match made with [ari] [Jun 3 22:06:13] DEBUG[28175] res_ari.c: Finding handler for channels [Jun 3 22:06:13] DEBUG[28175] res_ari.c: Checking channels [Jun 3 22:06:13] DEBUG[28175] res_ari.c: Got it! [Jun 3 22:06:13] DEBUG[28175] res_ari.c: Finding handler for i-0a321ef5a9fcf448c-1464991573.68 [Jun 3 22:06:13] DEBUG[28175] res_ari.c: Checking channelId [Jun 3 22:06:13] DEBUG[28175] res_ari.c: Got it! [Jun 3 22:06:13] DEBUG[28175] res_ari.c: Finding handler for continue [Jun 3 22:06:13] DEBUG[28175] res_ari.c: Checking continue [Jun 3 22:06:13] DEBUG[28175] res_ari.c: Got it! [Jun 3 22:06:13] DEBUG[28175] res_ari.c: Examining ARI response: 204 No Content [Jun 3 22:06:13] DEBUG[28175] http.c: HTTP keeping session open. status_code:204 [Jun 3 22:06:13] DEBUG[28175] http.c: HTTP idle timeout or peer closed connection. [Jun 3 22:06:13] DEBUG[28175] http.c: HTTP closing session. Top level [Jun 3 22:06:13] DEBUG[28169][C-0000000f] stasis/app.c: App 'switchboard' not subscribed to bridge '__AST_BRIDGE_ALL_TOPIC' [Jun 3 22:06:13] DEBUG[28169][C-0000000f] stasis/app.c: channel 'i-0a321ef5a9fcf448c-1464991573.68': is 0 interested in switchboard [Jun 3 22:06:13] DEBUG[28169][C-0000000f] stasis/app.c: channel 'i-0a321ef5a9fcf448c-1464991573.68' unsubscribed from switchboard [Jun 3 22:06:13] DEBUG[28020] ari/ari_websockets.c: Examining ARI event (length 417): {"application":"switchboard","type":"StasisEnd","timestamp":"2016-06-03T22:06:13.989+0000","channel":{"id":"i-0a321ef5a9fcf448c-1464991573.68","state":"Ring","name":"PJSIP/sip-standard-0000000f","caller":{"name":"","number":"sip-standard"},"language":"en","connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"default","exten":"0000","priority":3},"creationtime":"2016-06-03T22:06:13.787+0000"}} [Jun 3 22:06:13] DEBUG[28020] res_http_websocket.c: Writing websocket string of length 417 [Jun 3 22:06:13] DEBUG[28020] res_http_websocket.c: Writing websocket text frame, length 417 [Jun 3 22:06:13] DEBUG[28169][C-0000000f] pbx_variables.c: Function PJSIP_HEADER(read,X-BTcallID) result is '4-call-6309ed62-29d7-11e6-9c63-defe000026b4-v3' [Jun 3 22:06:13] DEBUG[28169][C-0000000f] pbx.c: Launching 'Stasis' [Jun 3 22:06:13] VERBOSE[28169][C-0000000f] pbx.c: Executing [0000@default:4] Stasis("PJSIP/sip-standard-0000000f", "4-call-6309ed62-29d7-11e6-9c63-defe000026b4-v3") in new stack [Jun 3 22:06:13] DEBUG[28169][C-0000000f] stasis/app.c: Channel 'i-0a321ef5a9fcf448c-1464991573.68' is 1 interested in 4-call-6309ed62-29d7-11e6-9c63-defe000026b4-v3 [Jun 3 22:06:13] DEBUG[28174] ari/ari_websockets.c: Examining ARI event (length 464): {"application":"4-call-6309ed62-29d7-11e6-9c63-defe000026b4-v3","type":"StasisStart","timestamp":"2016-06-03T22:06:13.989+0000","args":[],"channel":{"id":"i-0a321ef5a9fcf448c-1464991573.68","state":"Ring","name":"PJSIP/sip-standard-0000000f","caller":{"name":"","number":"sip-standard"},"language":"en","connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"default","exten":"0000","priority":4},"creationtime":"2016-06-03T22:06:13.787+0000"}} [Jun 3 22:06:13] DEBUG[28174] res_http_websocket.c: Writing websocket string of length 464 [Jun 3 22:06:13] DEBUG[28174] res_http_websocket.c: Writing websocket text frame, length 464 [Jun 3 22:06:14] DEBUG[28177] http.c: HTTP opening session. Top level [Jun 3 22:06:14] DEBUG[28177] http.c: HTTP Request URI is /ari/channels/i-0a321ef5a9fcf448c-1464991573.68/variable [Jun 3 22:06:14] DEBUG[28177] http.c: match request [ari/channels/i-0a321ef5a9fcf448c-1464991573.68/variable] with handler [httpstatus] len 10 [Jun 3 22:06:14] DEBUG[28177] http.c: match request [ari/channels/i-0a321ef5a9fcf448c-1464991573.68/variable] with handler [static] len 6 [Jun 3 22:06:14] DEBUG[28177] http.c: match request [ari/channels/i-0a321ef5a9fcf448c-1464991573.68/variable] with handler [ari] len 3 [Jun 3 22:06:14] DEBUG[28177] http.c: Match made with [ari] [Jun 3 22:06:14] DEBUG[28177] res_ari.c: Finding handler for channels [Jun 3 22:06:14] DEBUG[28177] res_ari.c: Checking channels [Jun 3 22:06:14] DEBUG[28177] res_ari.c: Got it! [Jun 3 22:06:14] DEBUG[28177] res_ari.c: Finding handler for i-0a321ef5a9fcf448c-1464991573.68 [Jun 3 22:06:14] DEBUG[28177] res_ari.c: Checking channelId [Jun 3 22:06:14] DEBUG[28177] res_ari.c: Got it! [Jun 3 22:06:14] DEBUG[28177] res_ari.c: Finding handler for variable [Jun 3 22:06:14] DEBUG[28177] res_ari.c: Checking continue [Jun 3 22:06:14] DEBUG[28177] res_ari.c: Checking redirect [Jun 3 22:06:14] DEBUG[28177] res_ari.c: Checking answer [Jun 3 22:06:14] DEBUG[28177] res_ari.c: Checking ring [Jun 3 22:06:14] DEBUG[28177] res_ari.c: Checking dtmf [Jun 3 22:06:14] DEBUG[28177] res_ari.c: Checking mute [Jun 3 22:06:14] DEBUG[28177] res_ari.c: Checking hold [Jun 3 22:06:14] DEBUG[28177] res_ari.c: Checking moh [Jun 3 22:06:14] DEBUG[28177] res_ari.c: Checking silence [Jun 3 22:06:14] DEBUG[28177] res_ari.c: Checking play [Jun 3 22:06:14] DEBUG[28177] res_ari.c: Checking record [Jun 3 22:06:14] DEBUG[28177] res_ari.c: Checking variable [Jun 3 22:06:14] DEBUG[28177] res_ari.c: Got it! [Jun 3 22:06:14] DEBUG[28177] http.c: HTTP consuming request body [Jun 3 22:06:14] DEBUG[28177] res_ari.c: Examining ARI response: 204 No Content [Jun 3 22:06:14] DEBUG[28177] http.c: HTTP keeping session open. status_code:204 [Jun 3 22:06:14] DEBUG[28177] http.c: HTTP idle timeout or peer closed connection. [Jun 3 22:06:14] DEBUG[28177] http.c: HTTP closing session. Top level [Jun 3 22:06:14] DEBUG[28178] http.c: HTTP opening session. Top level [Jun 3 22:06:14] DEBUG[28178] http.c: HTTP Request URI is /ari/channels/i-0a321ef5a9fcf448c-1464991573.68/variable [Jun 3 22:06:14] DEBUG[28178] http.c: match request [ari/channels/i-0a321ef5a9fcf448c-1464991573.68/variable] with handler [httpstatus] len 10 [Jun 3 22:06:14] DEBUG[28178] http.c: match request [ari/channels/i-0a321ef5a9fcf448c-1464991573.68/variable] with handler [static] len 6 [Jun 3 22:06:14] DEBUG[28178] http.c: match request [ari/channels/i-0a321ef5a9fcf448c-1464991573.68/variable] with handler [ari] len 3 [Jun 3 22:06:14] DEBUG[28178] http.c: Match made with [ari] [Jun 3 22:06:14] DEBUG[28178] res_ari.c: Finding handler for channels [Jun 3 22:06:14] DEBUG[28178] res_ari.c: Checking channels [Jun 3 22:06:14] DEBUG[28178] res_ari.c: Got it! [Jun 3 22:06:14] DEBUG[28178] res_ari.c: Finding handler for i-0a321ef5a9fcf448c-1464991573.68 [Jun 3 22:06:14] DEBUG[28178] res_ari.c: Checking channelId [Jun 3 22:06:14] DEBUG[28178] res_ari.c: Got it! [Jun 3 22:06:14] DEBUG[28178] res_ari.c: Finding handler for variable [Jun 3 22:06:14] DEBUG[28178] res_ari.c: Checking continue [Jun 3 22:06:14] DEBUG[28178] res_ari.c: Checking redirect [Jun 3 22:06:14] DEBUG[28178] res_ari.c: Checking answer [Jun 3 22:06:14] DEBUG[28178] res_ari.c: Checking ring [Jun 3 22:06:14] DEBUG[28178] res_ari.c: Checking dtmf [Jun 3 22:06:14] DEBUG[28178] res_ari.c: Checking mute [Jun 3 22:06:14] DEBUG[28178] res_ari.c: Checking hold [Jun 3 22:06:14] DEBUG[28178] res_ari.c: Checking moh [Jun 3 22:06:14] DEBUG[28178] res_ari.c: Checking silence [Jun 3 22:06:14] DEBUG[28178] res_ari.c: Checking play [Jun 3 22:06:14] DEBUG[28178] res_ari.c: Checking record [Jun 3 22:06:14] DEBUG[28178] res_ari.c: Checking variable [Jun 3 22:06:14] DEBUG[28178] res_ari.c: Got it! [Jun 3 22:06:14] DEBUG[28178] http.c: HTTP consuming request body [Jun 3 22:06:14] DEBUG[28178] res_ari.c: Examining ARI response: 204 No Content [Jun 3 22:06:14] DEBUG[28178] http.c: HTTP keeping session open. status_code:204 [Jun 3 22:06:14] DEBUG[28178] http.c: HTTP idle timeout or peer closed connection. [Jun 3 22:06:14] DEBUG[28178] http.c: HTTP closing session. Top level [Jun 3 22:06:14] DEBUG[28179] http.c: HTTP opening session. Top level [Jun 3 22:06:14] DEBUG[28179] http.c: HTTP Request URI is /ari/channels/i-0a321ef5a9fcf448c-1464991573.68/variable [Jun 3 22:06:14] DEBUG[28179] http.c: match request [ari/channels/i-0a321ef5a9fcf448c-1464991573.68/variable] with handler [httpstatus] len 10 [Jun 3 22:06:14] DEBUG[28179] http.c: match request [ari/channels/i-0a321ef5a9fcf448c-1464991573.68/variable] with handler [static] len 6 [Jun 3 22:06:14] DEBUG[28179] http.c: match request [ari/channels/i-0a321ef5a9fcf448c-1464991573.68/variable] with handler [ari] len 3 [Jun 3 22:06:14] DEBUG[28179] http.c: Match made with [ari] [Jun 3 22:06:14] DEBUG[28179] res_ari.c: Finding handler for channels [Jun 3 22:06:14] DEBUG[28179] res_ari.c: Checking channels [Jun 3 22:06:14] DEBUG[28179] res_ari.c: Got it! [Jun 3 22:06:14] DEBUG[28179] res_ari.c: Finding handler for i-0a321ef5a9fcf448c-1464991573.68 [Jun 3 22:06:14] DEBUG[28179] res_ari.c: Checking channelId [Jun 3 22:06:14] DEBUG[28179] res_ari.c: Got it! [Jun 3 22:06:14] DEBUG[28179] res_ari.c: Finding handler for variable [Jun 3 22:06:14] DEBUG[28179] res_ari.c: Checking continue [Jun 3 22:06:14] DEBUG[28179] res_ari.c: Checking redirect [Jun 3 22:06:14] DEBUG[28179] res_ari.c: Checking answer [Jun 3 22:06:14] DEBUG[28179] res_ari.c: Checking ring [Jun 3 22:06:14] DEBUG[28179] res_ari.c: Checking dtmf [Jun 3 22:06:14] DEBUG[28179] res_ari.c: Checking mute [Jun 3 22:06:14] DEBUG[28179] res_ari.c: Checking hold [Jun 3 22:06:14] DEBUG[28179] res_ari.c: Checking moh [Jun 3 22:06:14] DEBUG[28179] res_ari.c: Checking silence [Jun 3 22:06:14] DEBUG[28179] res_ari.c: Checking play [Jun 3 22:06:14] DEBUG[28179] res_ari.c: Checking record [Jun 3 22:06:14] DEBUG[28179] res_ari.c: Checking variable [Jun 3 22:06:14] DEBUG[28179] res_ari.c: Got it! [Jun 3 22:06:14] DEBUG[28179] http.c: HTTP consuming request body [Jun 3 22:06:14] DEBUG[28179] res_ari.c: Examining ARI response: 200 OK Content-type: application/json {"value":";tag=48720501ff51affco0"} [Jun 3 22:06:14] DEBUG[28179] http.c: HTTP keeping session open. status_code:200 [Jun 3 22:06:14] DEBUG[28179] http.c: HTTP idle timeout or peer closed connection. [Jun 3 22:06:14] DEBUG[28179] http.c: HTTP closing session. Top level [Jun 3 22:06:14] DEBUG[28180] http.c: HTTP opening session. Top level [Jun 3 22:06:14] DEBUG[28180] http.c: HTTP Request URI is /ari/channels/i-0a321ef5a9fcf448c-1464991573.68/answer [Jun 3 22:06:14] DEBUG[28180] http.c: match request [ari/channels/i-0a321ef5a9fcf448c-1464991573.68/answer] with handler [httpstatus] len 10 [Jun 3 22:06:14] DEBUG[28180] http.c: match request [ari/channels/i-0a321ef5a9fcf448c-1464991573.68/answer] with handler [static] len 6 [Jun 3 22:06:14] DEBUG[28180] http.c: match request [ari/channels/i-0a321ef5a9fcf448c-1464991573.68/answer] with handler [ari] len 3 [Jun 3 22:06:14] DEBUG[28180] http.c: Match made with [ari] [Jun 3 22:06:14] DEBUG[28180] res_ari.c: Finding handler for channels [Jun 3 22:06:14] DEBUG[28180] res_ari.c: Checking channels [Jun 3 22:06:14] DEBUG[28180] res_ari.c: Got it! [Jun 3 22:06:14] DEBUG[28180] res_ari.c: Finding handler for i-0a321ef5a9fcf448c-1464991573.68 [Jun 3 22:06:14] DEBUG[28180] res_ari.c: Checking channelId [Jun 3 22:06:14] DEBUG[28180] res_ari.c: Got it! [Jun 3 22:06:14] DEBUG[28180] res_ari.c: Finding handler for answer [Jun 3 22:06:14] DEBUG[28180] res_ari.c: Checking continue [Jun 3 22:06:14] DEBUG[28180] res_ari.c: Checking redirect [Jun 3 22:06:14] DEBUG[28180] res_ari.c: Checking answer [Jun 3 22:06:14] DEBUG[28180] res_ari.c: Got it! [Jun 3 22:06:14] DEBUG[28180] res_stasis_answer.c: i-0a321ef5a9fcf448c-1464991573.68: Sending answer command [Jun 3 22:06:14] DEBUG[28169][C-0000000f] res_stasis_answer.c: i-0a321ef5a9fcf448c-1464991573.68: Answering [Jun 3 22:06:14] DEBUG[28174] ari/ari_websockets.c: Examining ARI event (length 535): {"channel":{"id":"i-0a321ef5a9fcf448c-1464991573.68","state":"Ring","name":"PJSIP/sip-standard-0000000f","caller":{"name":"","number":"sip-standard"},"language":"en","connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"default","exten":"0000","priority":4},"creationtime":"2016-06-03T22:06:13.787+0000"},"application":"4-call-6309ed62-29d7-11e6-9c63-defe000026b4-v3","variable":"btCallID","type":"ChannelVarset","value":"4-call-6309ed62-29d7-11e6-9c63-defe000026b4-v3","timestamp":"2016-06-03T22:06:14.190+0000"} [Jun 3 22:06:14] DEBUG[18024] devicestate.c: No provider found, checking channel drivers for PJSIP - sip-standard [Jun 3 22:06:14] DEBUG[28174] res_http_websocket.c: Writing websocket string of length 535 [Jun 3 22:06:14] DEBUG[28174] res_http_websocket.c: Writing websocket text frame, length 535 [Jun 3 22:06:14] DEBUG[18024] devicestate.c: Changing state for PJSIP/sip-standard - state 2 (In use) [Jun 3 22:06:14] DEBUG[28174] ari/ari_websockets.c: Examining ARI event (length 530): {"channel":{"id":"i-0a321ef5a9fcf448c-1464991573.68","state":"Ring","name":"PJSIP/sip-standard-0000000f","caller":{"name":"","number":"sip-standard"},"language":"en","connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"default","exten":"0000","priority":4},"creationtime":"2016-06-03T22:06:13.787+0000"},"application":"4-call-6309ed62-29d7-11e6-9c63-defe000026b4-v3","variable":"app","type":"ChannelVarset","value":"4-call-6309ed62-29d7-11e6-9c63-defe000026b4-v3","timestamp":"2016-06-03T22:06:14.190+0000"} [Jun 3 22:06:14] DEBUG[28174] res_http_websocket.c: Writing websocket string of length 530 [Jun 3 22:06:14] DEBUG[28174] res_http_websocket.c: Writing websocket text frame, length 530 [Jun 3 22:06:14] DEBUG[18048] res_pjsip_session.c: Applying negotiated SDP media stream 'audio' using audio SDP handler [Jun 3 22:06:14] DEBUG[18048] netsock2.c: Splitting 'REDACTED' into... [Jun 3 22:06:14] DEBUG[18048] netsock2.c: ...host 'REDACTED' and port ''. [Jun 3 22:06:14] DEBUG[18048] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f4298115b08' [Jun 3 22:06:14] DEBUG[18048] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7f4288084e70 [Jun 3 22:06:14] DEBUG[18048] rtp_engine.c: Don't have a default tx payload type 2 format for m type on 0x7f4288084e70 [Jun 3 22:06:14] DEBUG[18048] rtp_engine.c: Setting tx payload type 4 based on m type on 0x7f4288084e70 [Jun 3 22:06:14] DEBUG[18048] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7f4288084e70 [Jun 3 22:06:14] DEBUG[28174] ari/ari_websockets.c: Examining ARI event (length 459): {"application":"4-call-6309ed62-29d7-11e6-9c63-defe000026b4-v3","type":"ChannelStateChange","timestamp":"2016-06-03T22:06:14.190+0000","channel":{"id":"i-0a321ef5a9fcf448c-1464991573.68","state":"Up","name":"PJSIP/sip-standard-0000000f","caller":{"name":"","number":"sip-standard"},"language":"en","connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"default","exten":"0000","priority":4},"creationtime":"2016-06-03T22:06:13.787+0000"}} [Jun 3 22:06:14] DEBUG[28174] res_http_websocket.c: Writing websocket string of length 459 [Jun 3 22:06:14] DEBUG[18048] rtp_engine.c: Setting tx payload type 18 based on m type on 0x7f4288084e70 [Jun 3 22:06:14] DEBUG[28174] res_http_websocket.c: Writing websocket text frame, length 459 [Jun 3 22:06:14] DEBUG[18048] rtp_engine.c: Don't have a default tx payload type 96 format for m type on 0x7f4288084e70 [Jun 3 22:06:14] DEBUG[18048] rtp_engine.c: Setting tx payload type 97 based on m type on 0x7f4288084e70 [Jun 3 22:06:14] DEBUG[18048] rtp_engine.c: Setting tx payload type 98 based on m type on 0x7f4288084e70 [Jun 3 22:06:14] DEBUG[18048] rtp_engine.c: Setting tx payload type 101 based on m type on 0x7f4288084e70 [Jun 3 22:06:14] DEBUG[18048] rtp_engine.c: Copying payload 0 (0x7f42981193b0) from 0x7f4288084e70 to 0x7f4298115cd0 [Jun 3 22:06:14] DEBUG[18048] rtp_engine.c: Copying payload 2 (0x7f4298123230) from 0x7f4288084e70 to 0x7f4298115cd0 [Jun 3 22:06:14] DEBUG[18048] rtp_engine.c: Copying payload 4 (0x7f42981236b0) from 0x7f4288084e70 to 0x7f4298115cd0 [Jun 3 22:06:14] DEBUG[18048] rtp_engine.c: Copying payload 8 (0x7f4298123c40) from 0x7f4288084e70 to 0x7f4298115cd0 [Jun 3 22:06:14] DEBUG[18048] rtp_engine.c: Copying payload 18 (0x7f42981240c0) from 0x7f4288084e70 to 0x7f4298115cd0 [Jun 3 22:06:14] DEBUG[18048] rtp_engine.c: Copying payload 97 (0x29d9c20) from 0x7f4288084e70 to 0x7f4298115cd0 [Jun 3 22:06:14] DEBUG[18048] rtp_engine.c: Copying payload 98 (0x29d9c60) from 0x7f4288084e70 to 0x7f4298115cd0 [Jun 3 22:06:14] DEBUG[18048] rtp_engine.c: Copying payload 101 (0x7f4298105ff0) from 0x7f4288084e70 to 0x7f4298115cd0 [Jun 3 22:06:14] DEBUG[18048] res_pjsip_session.c: Applied negotiated SDP media stream 'audio' using audio SDP handler [Jun 3 22:06:14] DEBUG[18048] res_pjsip_session.c: Method is INVITE, Response is 200 OK [Jun 3 22:06:14] DEBUG[18048] res_pjsip_multihomed.c: Re-wrote Contact URI host/port to REDACTED:5060 [Jun 3 22:06:14] DEBUG[18048] netsock2.c: Splitting '0.0.0.0:5060' into... [Jun 3 22:06:14] DEBUG[18048] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jun 3 22:06:14] DEBUG[18048] netsock2.c: Splitting 'REDACTED:5060' into... [Jun 3 22:06:14] DEBUG[18048] netsock2.c: ...host 'REDACTED' and port '5060'. [Jun 3 22:06:14] DEBUG[18048] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Jun 3 22:06:14] DEBUG[18048] res_pjsip_session.c: The state change pertains to the endpoint 'sip-standard(PJSIP/sip-standard-0000000f)' [Jun 3 22:06:14] DEBUG[18048] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f429800d618) [Jun 3 22:06:14] DEBUG[18048] res_pjsip_session.c: There is no transaction involved in this state change [Jun 3 22:06:14] DEBUG[18048] res_pjsip_session.c: The current inv state is CONNECTING [Jun 3 22:06:14] DEBUG[18048] res_pjsip_session.c: Source of transaction state change is TX_MSG [Jun 3 22:06:14] DEBUG[18048] res_pjsip_session.c: Sending response [Jun 3 22:06:14] DEBUG[18048] res_pjsip_session.c: Method is INVITE, Response is 200 OK [Jun 3 22:06:14] DEBUG[18048] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jun 3 22:06:14] DEBUG[18048] res_pjsip_session.c: The state change pertains to the endpoint 'sip-standard(PJSIP/sip-standard-0000000f)' [Jun 3 22:06:14] DEBUG[18048] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f429800d618) [Jun 3 22:06:14] DEBUG[18048] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f429800d618 [Jun 3 22:06:14] DEBUG[18048] res_pjsip_session.c: The current transaction state is Completed [Jun 3 22:06:14] DEBUG[18048] res_pjsip_session.c: The transaction state change event is TX_MSG [Jun 3 22:06:14] DEBUG[18048] res_pjsip_session.c: The current inv state is CONNECTING [Jun 3 22:06:14] DEBUG[18048] res_pjsip_session.c: Sending response [Jun 3 22:06:14] DEBUG[18048] res_pjsip_session.c: Method is INVITE, Response is 200 OK [Jun 3 22:06:14] DEBUG[28180] res_ari.c: Examining ARI response: 204 No Content [Jun 3 22:06:14] DEBUG[28180] http.c: HTTP keeping session open. status_code:204 [Jun 3 22:06:14] DEBUG[28180] http.c: HTTP idle timeout or peer closed connection. [Jun 3 22:06:14] DEBUG[28180] http.c: HTTP closing session. Top level [Jun 3 22:06:14] DEBUG[18047] netsock2.c: Splitting 'REDACTED:5060' into... [Jun 3 22:06:14] DEBUG[18047] netsock2.c: ...host 'REDACTED' and port '5060'. [Jun 3 22:06:14] DEBUG[18047] netsock2.c: Splitting '0.0.0.0:5060' into... [Jun 3 22:06:14] DEBUG[18047] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jun 3 22:06:14] DEBUG[18047] res_pjsip/pjsip_distributor.c: Searching for serializer on dialog dlg0x7f4298015f88 for (null) [Jun 3 22:06:14] DEBUG[18047] res_pjsip/pjsip_distributor.c: Found serializer pjsip/session/sip-standard-00000079 on dialog dlg0x7f4298015f88 [Jun 3 22:06:14] DEBUG[18048] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jun 3 22:06:14] DEBUG[18048] res_pjsip_session.c: The state change pertains to the endpoint 'sip-standard(PJSIP/sip-standard-0000000f)' [Jun 3 22:06:14] DEBUG[18048] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Jun 3 22:06:14] DEBUG[18048] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f429800d618 [Jun 3 22:06:14] DEBUG[18048] res_pjsip_session.c: The current transaction state is Terminated [Jun 3 22:06:14] DEBUG[18048] res_pjsip_session.c: The transaction state change event is USER [Jun 3 22:06:14] DEBUG[18048] res_pjsip_session.c: The current inv state is CONNECTING [Jun 3 22:06:14] DEBUG[18048] res_pjsip_session.c: Function session_inv_on_state_changed called on event RX_MSG [Jun 3 22:06:14] DEBUG[18048] res_pjsip_session.c: The state change pertains to the endpoint 'sip-standard(PJSIP/sip-standard-0000000f)' [Jun 3 22:06:14] DEBUG[18048] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Jun 3 22:06:14] DEBUG[18048] res_pjsip_session.c: There is no transaction involved in this state change [Jun 3 22:06:14] DEBUG[18048] res_pjsip_session.c: The current inv state is CONFIRMED [Jun 3 22:06:14] DEBUG[18048] res_pjsip_session.c: Received request [Jun 3 22:06:14] DEBUG[18048] res_pjsip_session.c: Method is ACK [Jun 3 22:06:14] DEBUG[28181] http.c: HTTP opening session. Top level [Jun 3 22:06:14] DEBUG[28181] http.c: HTTP Request URI is /ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873 [Jun 3 22:06:14] DEBUG[28181] http.c: match request [ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873] with handler [httpstatus] len 10 [Jun 3 22:06:14] DEBUG[28181] http.c: match request [ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873] with handler [static] len 6 [Jun 3 22:06:14] DEBUG[28181] http.c: match request [ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873] with handler [ari] len 3 [Jun 3 22:06:14] DEBUG[28181] http.c: Match made with [ari] [Jun 3 22:06:14] DEBUG[28181] res_ari.c: Finding handler for bridges [Jun 3 22:06:14] DEBUG[28181] res_ari.c: Checking channels [Jun 3 22:06:14] DEBUG[28181] res_ari.c: Checking asterisk [Jun 3 22:06:14] DEBUG[28181] res_ari.c: Checking deviceStates [Jun 3 22:06:14] DEBUG[28181] res_ari.c: Checking bridges [Jun 3 22:06:14] DEBUG[28181] res_ari.c: Got it! [Jun 3 22:06:14] DEBUG[28181] res_ari.c: Finding handler for 632d4320-29d7-11e6-895b-125fb2bca873 [Jun 3 22:06:14] DEBUG[28181] res_ari.c: Checking bridgeId [Jun 3 22:06:14] DEBUG[28181] res_ari.c: Got it! [Jun 3 22:06:14] DEBUG[28181] res_ari.c: Examining ARI response: 404 Not Found Content-type: application/json {"message":"Bridge not found"} [Jun 3 22:06:14] DEBUG[28181] http.c: HTTP keeping session open. status_code:404 [Jun 3 22:06:14] DEBUG[28181] http.c: HTTP idle timeout or peer closed connection. [Jun 3 22:06:14] DEBUG[28181] http.c: HTTP closing session. Top level [Jun 3 22:06:14] DEBUG[28182] http.c: HTTP opening session. Top level [Jun 3 22:06:14] DEBUG[28182] http.c: HTTP Request URI is /ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873 [Jun 3 22:06:14] DEBUG[28182] http.c: match request [ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873] with handler [httpstatus] len 10 [Jun 3 22:06:14] DEBUG[28182] http.c: match request [ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873] with handler [static] len 6 [Jun 3 22:06:14] DEBUG[28182] http.c: match request [ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873] with handler [ari] len 3 [Jun 3 22:06:14] DEBUG[28182] http.c: Match made with [ari] [Jun 3 22:06:14] DEBUG[28182] res_ari.c: Finding handler for bridges [Jun 3 22:06:14] DEBUG[28182] res_ari.c: Checking channels [Jun 3 22:06:14] DEBUG[28182] res_ari.c: Checking asterisk [Jun 3 22:06:14] DEBUG[28182] res_ari.c: Checking deviceStates [Jun 3 22:06:14] DEBUG[28182] res_ari.c: Checking bridges [Jun 3 22:06:14] DEBUG[28182] res_ari.c: Got it! [Jun 3 22:06:14] DEBUG[28182] res_ari.c: Finding handler for 632d4320-29d7-11e6-895b-125fb2bca873 [Jun 3 22:06:14] DEBUG[28182] res_ari.c: Checking bridgeId [Jun 3 22:06:14] DEBUG[28182] res_ari.c: Got it! [Jun 3 22:06:14] DEBUG[28182] res_ari.c: Examining ARI response: 404 Not Found Content-type: application/json {"message":"Bridge not found"} [Jun 3 22:06:14] DEBUG[28182] http.c: HTTP keeping session open. status_code:404 [Jun 3 22:06:14] DEBUG[28182] http.c: HTTP idle timeout or peer closed connection. [Jun 3 22:06:14] DEBUG[28182] http.c: HTTP closing session. Top level [Jun 3 22:06:14] DEBUG[28183] http.c: HTTP opening session. Top level [Jun 3 22:06:14] DEBUG[28183] http.c: HTTP Request URI is /ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873 [Jun 3 22:06:14] DEBUG[28183] http.c: match request [ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873] with handler [httpstatus] len 10 [Jun 3 22:06:14] DEBUG[28183] http.c: match request [ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873] with handler [static] len 6 [Jun 3 22:06:14] DEBUG[28183] http.c: match request [ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873] with handler [ari] len 3 [Jun 3 22:06:14] DEBUG[28183] http.c: Match made with [ari] [Jun 3 22:06:14] DEBUG[28183] res_ari.c: Finding handler for bridges [Jun 3 22:06:14] DEBUG[28183] res_ari.c: Checking channels [Jun 3 22:06:14] DEBUG[28183] res_ari.c: Checking asterisk [Jun 3 22:06:14] DEBUG[28183] res_ari.c: Checking deviceStates [Jun 3 22:06:14] DEBUG[28183] res_ari.c: Checking bridges [Jun 3 22:06:14] DEBUG[28183] res_ari.c: Got it! [Jun 3 22:06:14] DEBUG[28183] res_ari.c: Finding handler for 632d4320-29d7-11e6-895b-125fb2bca873 [Jun 3 22:06:14] DEBUG[28183] res_ari.c: Checking bridgeId [Jun 3 22:06:14] DEBUG[28183] res_ari.c: Got it! [Jun 3 22:06:14] DEBUG[28183] res_ari.c: Examining ARI response: 404 Not Found Content-type: application/json {"message":"Bridge not found"} [Jun 3 22:06:14] DEBUG[28183] http.c: HTTP keeping session open. status_code:404 [Jun 3 22:06:14] DEBUG[28183] http.c: HTTP idle timeout or peer closed connection. [Jun 3 22:06:14] DEBUG[28183] http.c: HTTP closing session. Top level [Jun 3 22:06:14] DEBUG[28184] http.c: HTTP opening session. Top level [Jun 3 22:06:14] DEBUG[28184] http.c: HTTP Request URI is /ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873 [Jun 3 22:06:14] DEBUG[28184] http.c: match request [ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873] with handler [httpstatus] len 10 [Jun 3 22:06:14] DEBUG[28184] http.c: match request [ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873] with handler [static] len 6 [Jun 3 22:06:14] DEBUG[28184] http.c: match request [ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873] with handler [ari] len 3 [Jun 3 22:06:14] DEBUG[28184] http.c: Match made with [ari] [Jun 3 22:06:14] DEBUG[28184] res_ari.c: Finding handler for bridges [Jun 3 22:06:14] DEBUG[28184] res_ari.c: Checking channels [Jun 3 22:06:14] DEBUG[28184] res_ari.c: Checking asterisk [Jun 3 22:06:14] DEBUG[28184] res_ari.c: Checking deviceStates [Jun 3 22:06:14] DEBUG[28184] res_ari.c: Checking bridges [Jun 3 22:06:14] DEBUG[28184] res_ari.c: Got it! [Jun 3 22:06:14] DEBUG[28184] res_ari.c: Finding handler for 632d4320-29d7-11e6-895b-125fb2bca873 [Jun 3 22:06:14] DEBUG[28184] res_ari.c: Checking bridgeId [Jun 3 22:06:14] DEBUG[28184] res_ari.c: Got it! [Jun 3 22:06:14] DEBUG[28184] res_ari.c: Examining ARI response: 404 Not Found Content-type: application/json {"message":"Bridge not found"} [Jun 3 22:06:14] DEBUG[28184] http.c: HTTP keeping session open. status_code:404 [Jun 3 22:06:14] DEBUG[28184] http.c: HTTP idle timeout or peer closed connection. [Jun 3 22:06:14] DEBUG[28184] http.c: HTTP closing session. Top level [Jun 3 22:06:14] DEBUG[28185] http.c: HTTP opening session. Top level [Jun 3 22:06:14] DEBUG[28185] http.c: HTTP Request URI is /ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873 [Jun 3 22:06:14] DEBUG[28185] http.c: match request [ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873] with handler [httpstatus] len 10 [Jun 3 22:06:14] DEBUG[28185] http.c: match request [ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873] with handler [static] len 6 [Jun 3 22:06:14] DEBUG[28185] http.c: match request [ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873] with handler [ari] len 3 [Jun 3 22:06:14] DEBUG[28185] http.c: Match made with [ari] [Jun 3 22:06:14] DEBUG[28185] res_ari.c: Finding handler for bridges [Jun 3 22:06:14] DEBUG[28185] res_ari.c: Checking channels [Jun 3 22:06:14] DEBUG[28185] res_ari.c: Checking asterisk [Jun 3 22:06:14] DEBUG[28185] res_ari.c: Checking deviceStates [Jun 3 22:06:14] DEBUG[28185] res_ari.c: Checking bridges [Jun 3 22:06:14] DEBUG[28185] res_ari.c: Got it! [Jun 3 22:06:14] DEBUG[28185] res_ari.c: Finding handler for 632d4320-29d7-11e6-895b-125fb2bca873 [Jun 3 22:06:14] DEBUG[28185] res_ari.c: Checking bridgeId [Jun 3 22:06:14] DEBUG[28185] res_ari.c: Got it! [Jun 3 22:06:14] DEBUG[28185] res_ari.c: Examining ARI response: 404 Not Found Content-type: application/json {"message":"Bridge not found"} [Jun 3 22:06:14] DEBUG[28185] http.c: HTTP keeping session open. status_code:404 [Jun 3 22:06:14] DEBUG[28185] http.c: HTTP idle timeout or peer closed connection. [Jun 3 22:06:14] DEBUG[28185] http.c: HTTP closing session. Top level [Jun 3 22:06:14] DEBUG[28186] http.c: HTTP opening session. Top level [Jun 3 22:06:14] DEBUG[28186] http.c: HTTP Request URI is /ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873 [Jun 3 22:06:14] DEBUG[28186] http.c: match request [ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873] with handler [httpstatus] len 10 [Jun 3 22:06:14] DEBUG[28186] http.c: match request [ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873] with handler [static] len 6 [Jun 3 22:06:14] DEBUG[28186] http.c: match request [ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873] with handler [ari] len 3 [Jun 3 22:06:14] DEBUG[28186] http.c: Match made with [ari] [Jun 3 22:06:14] DEBUG[28186] res_ari.c: Finding handler for bridges [Jun 3 22:06:14] DEBUG[28186] res_ari.c: Checking channels [Jun 3 22:06:14] DEBUG[28186] res_ari.c: Checking asterisk [Jun 3 22:06:14] DEBUG[28186] res_ari.c: Checking deviceStates [Jun 3 22:06:14] DEBUG[28186] res_ari.c: Checking bridges [Jun 3 22:06:14] DEBUG[28186] res_ari.c: Got it! [Jun 3 22:06:14] DEBUG[28186] res_ari.c: Finding handler for 632d4320-29d7-11e6-895b-125fb2bca873 [Jun 3 22:06:14] DEBUG[28186] res_ari.c: Checking bridgeId [Jun 3 22:06:14] DEBUG[28186] res_ari.c: Got it! [Jun 3 22:06:14] DEBUG[28186] res_ari.c: Examining ARI response: 404 Not Found Content-type: application/json {"message":"Bridge not found"} [Jun 3 22:06:14] DEBUG[28186] http.c: HTTP keeping session open. status_code:404 [Jun 3 22:06:14] DEBUG[28186] http.c: HTTP idle timeout or peer closed connection. [Jun 3 22:06:14] DEBUG[28186] http.c: HTTP closing session. Top level [Jun 3 22:06:14] DEBUG[28187] http.c: HTTP opening session. Top level [Jun 3 22:06:14] DEBUG[28187] http.c: HTTP Request URI is /ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873?type=mixing&name=default [Jun 3 22:06:14] DEBUG[28187] http.c: match request [ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873] with handler [httpstatus] len 10 [Jun 3 22:06:14] DEBUG[28187] http.c: match request [ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873] with handler [static] len 6 [Jun 3 22:06:14] DEBUG[28187] http.c: match request [ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873] with handler [ari] len 3 [Jun 3 22:06:14] DEBUG[28187] http.c: Match made with [ari] [Jun 3 22:06:14] DEBUG[28187] res_ari.c: Finding handler for bridges [Jun 3 22:06:14] DEBUG[28187] res_ari.c: Checking channels [Jun 3 22:06:14] DEBUG[28187] res_ari.c: Checking asterisk [Jun 3 22:06:14] DEBUG[28187] res_ari.c: Checking deviceStates [Jun 3 22:06:14] DEBUG[28187] res_ari.c: Checking bridges [Jun 3 22:06:14] DEBUG[28187] res_ari.c: Got it! [Jun 3 22:06:14] DEBUG[28187] res_ari.c: Finding handler for 632d4320-29d7-11e6-895b-125fb2bca873 [Jun 3 22:06:14] DEBUG[28187] res_ari.c: Checking bridgeId [Jun 3 22:06:14] DEBUG[28187] res_ari.c: Got it! [Jun 3 22:06:14] DEBUG[28187] bridge.c: Bridge technology softmix has less preference than simple_bridge (10 <= 50). Skipping. [Jun 3 22:06:14] DEBUG[28187] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Jun 3 22:06:14] DEBUG[28187] bridge_native_rtp.c: Bridge '632d4320-29d7-11e6-895b-125fb2bca873' can not use native RTP bridge as two channels are required [Jun 3 22:06:14] DEBUG[28187] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Jun 3 22:06:14] DEBUG[28187] bridge.c: Chose bridge technology simple_bridge [Jun 3 22:06:14] DEBUG[28187] bridge.c: Bridge 632d4320-29d7-11e6-895b-125fb2bca873: calling simple_bridge technology constructor [Jun 3 22:06:14] DEBUG[28187] bridge.c: Bridge 632d4320-29d7-11e6-895b-125fb2bca873: calling simple_bridge technology start [Jun 3 22:06:14] DEBUG[28187] res_ari.c: Examining ARI response: 200 OK Content-type: application/json {"id":"632d4320-29d7-11e6-895b-125fb2bca873","channels":[],"name":"default","technology":"simple_bridge","bridge_class":"stasis","creator":"Stasis","bridge_type":"mixing"} [Jun 3 22:06:14] DEBUG[28187] http.c: HTTP keeping session open. status_code:200 [Jun 3 22:06:14] DEBUG[28187] http.c: HTTP idle timeout or peer closed connection. [Jun 3 22:06:14] DEBUG[28187] http.c: HTTP closing session. Top level [Jun 3 22:06:14] DEBUG[28188] http.c: HTTP opening session. Top level [Jun 3 22:06:14] DEBUG[28188] http.c: HTTP Request URI is /ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873/addChannel?channel=i-0a321ef5a9fcf448c-1464991573.68 [Jun 3 22:06:14] DEBUG[28188] http.c: match request [ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873/addChannel] with handler [httpstatus] len 10 [Jun 3 22:06:14] DEBUG[28188] http.c: match request [ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873/addChannel] with handler [static] len 6 [Jun 3 22:06:14] DEBUG[28188] http.c: match request [ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873/addChannel] with handler [ari] len 3 [Jun 3 22:06:14] DEBUG[28188] http.c: Match made with [ari] [Jun 3 22:06:14] DEBUG[28188] res_ari.c: Finding handler for bridges [Jun 3 22:06:14] DEBUG[28188] res_ari.c: Checking channels [Jun 3 22:06:14] DEBUG[28188] res_ari.c: Checking asterisk [Jun 3 22:06:14] DEBUG[28188] res_ari.c: Checking deviceStates [Jun 3 22:06:14] DEBUG[28188] res_ari.c: Checking bridges [Jun 3 22:06:14] DEBUG[28188] res_ari.c: Got it! [Jun 3 22:06:14] DEBUG[28188] res_ari.c: Finding handler for 632d4320-29d7-11e6-895b-125fb2bca873 [Jun 3 22:06:14] DEBUG[28188] res_ari.c: Checking bridgeId [Jun 3 22:06:14] DEBUG[28188] res_ari.c: Got it! [Jun 3 22:06:14] DEBUG[28188] res_ari.c: Finding handler for addChannel [Jun 3 22:06:14] DEBUG[28188] res_ari.c: Checking addChannel [Jun 3 22:06:14] DEBUG[28188] res_ari.c: Got it! [Jun 3 22:06:14] DEBUG[28188] stasis/control.c: i-0a321ef5a9fcf448c-1464991573.68: Sending channel add_to_bridge command [Jun 3 22:06:14] DEBUG[28169][C-0000000f] bridge_roles.c: Roles did not exist on channel PJSIP/sip-standard-0000000f [Jun 3 22:06:14] DEBUG[28169][C-0000000f] stasis/control.c: i-0a321ef5a9fcf448c-1464991573.68: Adding to bridge 632d4320-29d7-11e6-895b-125fb2bca873 [Jun 3 22:06:14] DEBUG[28169][C-0000000f] stasis/app.c: Bridge '632d4320-29d7-11e6-895b-125fb2bca873' is 1 interested in 4-call-6309ed62-29d7-11e6-9c63-defe000026b4-v3 [Jun 3 22:06:14] DEBUG[28189][C-0000000f] bridge_channel.c: Bridge 632d4320-29d7-11e6-895b-125fb2bca873: 0x7f429409f6a8(PJSIP/sip-standard-0000000f) is joining [Jun 3 22:06:14] DEBUG[28189][C-0000000f] bridge_channel.c: Bridge 632d4320-29d7-11e6-895b-125fb2bca873: pushing 0x7f429409f6a8(PJSIP/sip-standard-0000000f) [Jun 3 22:06:14] VERBOSE[28189][C-0000000f] bridge_channel.c: Channel PJSIP/sip-standard-0000000f joined 'simple_bridge' stasis-bridge <632d4320-29d7-11e6-895b-125fb2bca873> [Jun 3 22:06:14] DEBUG[28189][C-0000000f] bridge.c: Bridge technology softmix does not have any capabilities we want. [Jun 3 22:06:14] DEBUG[28189][C-0000000f] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Jun 3 22:06:14] DEBUG[28189][C-0000000f] bridge_native_rtp.c: Bridge '632d4320-29d7-11e6-895b-125fb2bca873' can not use native RTP bridge as two channels are required [Jun 3 22:06:14] DEBUG[28189][C-0000000f] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Jun 3 22:06:14] DEBUG[28189][C-0000000f] bridge.c: Chose bridge technology simple_bridge [Jun 3 22:06:14] DEBUG[28189][C-0000000f] bridge.c: Bridge 632d4320-29d7-11e6-895b-125fb2bca873 is already using the new technology. [Jun 3 22:06:14] DEBUG[28189][C-0000000f] bridge.c: Bridge 632d4320-29d7-11e6-895b-125fb2bca873: 0x7f429409f6a8(PJSIP/sip-standard-0000000f) is joining simple_bridge technology [Jun 3 22:06:14] DEBUG[28189][C-0000000f] res_rtp_asterisk.c: 0x7f4298119640 -- Probation learning mode pass with source address REDACTED:16452 [Jun 3 22:06:14] VERBOSE[28189][C-0000000f] res_rtp_asterisk.c: 0x7f4298119640 -- Probation passed - setting RTP source address to REDACTED:16452 [Jun 3 22:06:14] DEBUG[28189][C-0000000f] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f4298115b08' [Jun 3 22:06:14] DEBUG[28188] res_ari.c: Examining ARI response: 204 No Content [Jun 3 22:06:14] DEBUG[28188] http.c: HTTP keeping session open. status_code:204 [Jun 3 22:06:14] DEBUG[28174] ari/ari_websockets.c: Examining ARI event (length 677): {"application":"4-call-6309ed62-29d7-11e6-9c63-defe000026b4-v3","type":"ChannelEnteredBridge","bridge":{"id":"632d4320-29d7-11e6-895b-125fb2bca873","channels":["i-0a321ef5a9fcf448c-1464991573.68"],"name":"default","technology":"simple_bridge","bridge_class":"stasis","creator":"Stasis","bridge_type":"mixing"},"timestamp":"2016-06-03T22:06:14.264+0000","channel":{"id":"i-0a321ef5a9fcf448c-1464991573.68","state":"Up","name":"PJSIP/sip-standard-0000000f","caller":{"name":"","number":"sip-standard"},"language":"en","connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"default","exten":"0000","priority":4},"creationtime":"2016-06-03T22:06:13.787+0000"}} [Jun 3 22:06:14] DEBUG[28174] res_http_websocket.c: Writing websocket string of length 677 [Jun 3 22:06:14] DEBUG[28174] res_http_websocket.c: Writing websocket text frame, length 677 [Jun 3 22:06:14] DEBUG[28169][C-0000000f] stasis/app.c: App '4-call-6309ed62-29d7-11e6-9c63-defe000026b4-v3' not subscribed to bridge '__AST_BRIDGE_ALL_TOPIC' [Jun 3 22:06:14] DEBUG[28169][C-0000000f] stasis/app.c: Bridge '632d4320-29d7-11e6-895b-125fb2bca873' is 2 interested in 4-call-6309ed62-29d7-11e6-9c63-defe000026b4-v3 [Jun 3 22:06:14] DEBUG[28188] http.c: HTTP idle timeout or peer closed connection. [Jun 3 22:06:14] DEBUG[28188] http.c: HTTP closing session. Top level [Jun 3 22:06:14] DEBUG[28190] http.c: HTTP opening session. Top level [Jun 3 22:06:14] DEBUG[28190] http.c: HTTP Request URI is /ari/channels/i-0a321ef5a9fcf448c-1464991573.68/variable [Jun 3 22:06:14] DEBUG[28190] http.c: match request [ari/channels/i-0a321ef5a9fcf448c-1464991573.68/variable] with handler [httpstatus] len 10 [Jun 3 22:06:14] DEBUG[28190] http.c: match request [ari/channels/i-0a321ef5a9fcf448c-1464991573.68/variable] with handler [static] len 6 [Jun 3 22:06:14] DEBUG[28190] http.c: match request [ari/channels/i-0a321ef5a9fcf448c-1464991573.68/variable] with handler [ari] len 3 [Jun 3 22:06:14] DEBUG[28190] http.c: Match made with [ari] [Jun 3 22:06:14] DEBUG[28190] res_ari.c: Finding handler for channels [Jun 3 22:06:14] DEBUG[28190] res_ari.c: Checking channels [Jun 3 22:06:14] DEBUG[28190] res_ari.c: Got it! [Jun 3 22:06:14] DEBUG[28190] res_ari.c: Finding handler for i-0a321ef5a9fcf448c-1464991573.68 [Jun 3 22:06:14] DEBUG[28190] res_ari.c: Checking channelId [Jun 3 22:06:14] DEBUG[28190] res_ari.c: Got it! [Jun 3 22:06:14] DEBUG[28190] res_ari.c: Finding handler for variable [Jun 3 22:06:14] DEBUG[28190] res_ari.c: Checking continue [Jun 3 22:06:14] DEBUG[28190] res_ari.c: Checking redirect [Jun 3 22:06:14] DEBUG[28190] res_ari.c: Checking answer [Jun 3 22:06:14] DEBUG[28190] res_ari.c: Checking ring [Jun 3 22:06:14] DEBUG[28190] res_ari.c: Checking dtmf [Jun 3 22:06:14] DEBUG[28190] res_ari.c: Checking mute [Jun 3 22:06:14] DEBUG[28190] res_ari.c: Checking hold [Jun 3 22:06:14] DEBUG[28190] res_ari.c: Checking moh [Jun 3 22:06:14] DEBUG[28190] res_ari.c: Checking silence [Jun 3 22:06:14] DEBUG[28190] res_ari.c: Checking play [Jun 3 22:06:14] DEBUG[28190] res_ari.c: Checking record [Jun 3 22:06:14] DEBUG[28190] res_ari.c: Checking variable [Jun 3 22:06:14] DEBUG[28190] res_ari.c: Got it! [Jun 3 22:06:14] DEBUG[28190] http.c: HTTP consuming request body [Jun 3 22:06:14] DEBUG[28190] pbx_variables.c: Result of 'btCallID' is '4-call-6309ed62-29d7-11e6-9c63-defe000026b4-v3' [Jun 3 22:06:14] DEBUG[28190] res_ari.c: Examining ARI response: 200 OK Content-type: application/json {"value":"4-call-6309ed62-29d7-11e6-9c63-defe000026b4-v3"} [Jun 3 22:06:14] DEBUG[28190] http.c: HTTP keeping session open. status_code:200 [Jun 3 22:06:14] DEBUG[28190] http.c: HTTP idle timeout or peer closed connection. [Jun 3 22:06:14] DEBUG[28190] http.c: HTTP closing session. Top level [Jun 3 22:06:14] DEBUG[28191] http.c: HTTP opening session. Top level [Jun 3 22:06:14] DEBUG[28191] http.c: HTTP Request URI is /ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873/play [Jun 3 22:06:14] DEBUG[28191] http.c: match request [ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873/play] with handler [httpstatus] len 10 [Jun 3 22:06:14] DEBUG[28191] http.c: match request [ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873/play] with handler [static] len 6 [Jun 3 22:06:14] DEBUG[28191] http.c: match request [ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873/play] with handler [ari] len 3 [Jun 3 22:06:14] DEBUG[28191] http.c: Match made with [ari] [Jun 3 22:06:14] DEBUG[28191] http.c: HTTP consuming request body [Jun 3 22:06:14] DEBUG[28191] res_ari.c: Finding handler for bridges [Jun 3 22:06:14] DEBUG[28191] res_ari.c: Checking channels [Jun 3 22:06:14] DEBUG[28191] res_ari.c: Checking asterisk [Jun 3 22:06:14] DEBUG[28191] res_ari.c: Checking deviceStates [Jun 3 22:06:14] DEBUG[28191] res_ari.c: Checking bridges [Jun 3 22:06:14] DEBUG[28191] res_ari.c: Got it! [Jun 3 22:06:14] DEBUG[28191] res_ari.c: Finding handler for 632d4320-29d7-11e6-895b-125fb2bca873 [Jun 3 22:06:14] DEBUG[28191] res_ari.c: Checking bridgeId [Jun 3 22:06:14] DEBUG[28191] res_ari.c: Got it! [Jun 3 22:06:14] DEBUG[28191] res_ari.c: Finding handler for play [Jun 3 22:06:14] DEBUG[28191] res_ari.c: Checking addChannel [Jun 3 22:06:14] DEBUG[28191] res_ari.c: Checking removeChannel [Jun 3 22:06:14] DEBUG[28191] res_ari.c: Checking moh [Jun 3 22:06:14] DEBUG[28191] res_ari.c: Checking play [Jun 3 22:06:14] DEBUG[28191] res_ari.c: Got it! [Jun 3 22:06:14] DEBUG[28191] bridge_roles.c: Set role 'announcer' [Jun 3 22:06:14] DEBUG[28191] ari/resource_bridges.c: Created announcer channel 'Announcer/ARI-00000013;1' [Jun 3 22:06:14] DEBUG[28192] bridge_channel.c: Bridge 632d4320-29d7-11e6-895b-125fb2bca873: 0x7f4284081dd8(Announcer/ARI-00000013;2) is joining [Jun 3 22:06:14] DEBUG[28192] bridge_channel.c: Bridge 632d4320-29d7-11e6-895b-125fb2bca873: pushing 0x7f4284081dd8(Announcer/ARI-00000013;2) [Jun 3 22:06:14] DEBUG[28192] bridge_roles.c: Set role 'announcer' [Jun 3 22:06:14] VERBOSE[28192] bridge_channel.c: Channel Announcer/ARI-00000013;2 joined 'simple_bridge' stasis-bridge <632d4320-29d7-11e6-895b-125fb2bca873> [Jun 3 22:06:14] DEBUG[28192] bridge.c: Bridge technology softmix does not have any capabilities we want. [Jun 3 22:06:14] DEBUG[28192] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Jun 3 22:06:14] DEBUG[28192] bridge_native_rtp.c: Bridge '632d4320-29d7-11e6-895b-125fb2bca873' can not use native RTP bridge as it was forbidden while getting details [Jun 3 22:06:14] DEBUG[28192] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Jun 3 22:06:14] DEBUG[28192] bridge.c: Chose bridge technology simple_bridge [Jun 3 22:06:14] DEBUG[28192] bridge.c: Bridge 632d4320-29d7-11e6-895b-125fb2bca873 is already using the new technology. [Jun 3 22:06:14] DEBUG[28192] bridge.c: Bridge 632d4320-29d7-11e6-895b-125fb2bca873: 0x7f4284081dd8(Announcer/ARI-00000013;2) is joining simple_bridge technology [Jun 3 22:06:14] DEBUG[28192] channel.c: Channel PJSIP/sip-standard-0000000f setting write format path: slin -> ulaw [Jun 3 22:06:14] DEBUG[28192] channel.c: Channel PJSIP/sip-standard-0000000f setting read format path: ulaw -> slin [Jun 3 22:06:14] DEBUG[28174] ari/ari_websockets.c: Examining ARI event (length 513): {"channel":{"id":"i-0a321ef5a9fcf448c-1464991573.68","state":"Up","name":"PJSIP/sip-standard-0000000f","caller":{"name":"","number":"sip-standard"},"language":"en","connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"default","exten":"0000","priority":4},"creationtime":"2016-06-03T22:06:13.787+0000"},"application":"4-call-6309ed62-29d7-11e6-9c63-defe000026b4-v3","variable":"BRIDGEPEER","type":"ChannelVarset","value":"Announcer/ARI-00000013;2","timestamp":"2016-06-03T22:06:14.272+0000"} [Jun 3 22:06:14] DEBUG[28174] res_http_websocket.c: Writing websocket string of length 513 [Jun 3 22:06:14] DEBUG[28174] res_http_websocket.c: Writing websocket text frame, length 513 [Jun 3 22:06:14] DEBUG[28189][C-0000000f] channel.c: PJSIP/sip-standard-0000000f: Dropping redundant connected line update "" <>. [Jun 3 22:06:14] DEBUG[28191] res_stasis_playback.c: i-0a321ef5a9fcf448c-1464991574.69: Sending play(tone:congestion) command [Jun 3 22:06:14] DEBUG[28191] res_ari.c: Examining ARI response: 201 Created Location: /playback/2f530220-cd75-497e-a3be-0d2f820d83ba Content-type: application/json {"id":"2f530220-cd75-497e-a3be-0d2f820d83ba","media_uri":"tone:congestion","target_uri":"bridge:632d4320-29d7-11e6-895b-125fb2bca873","language":"en","state":"queued"} [Jun 3 22:06:14] DEBUG[28191] http.c: HTTP keeping session open. status_code:201 [Jun 3 22:06:14] DEBUG[28193][C-0000000f] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jun 3 22:06:14] DEBUG[28174] ari/ari_websockets.c: Examining ARI event (length 269): {"application":"4-call-6309ed62-29d7-11e6-9c63-defe000026b4-v3","type":"PlaybackStarted","playback":{"id":"2f530220-cd75-497e-a3be-0d2f820d83ba","media_uri":"tone:congestion","target_uri":"bridge:632d4320-29d7-11e6-895b-125fb2bca873","language":"en","state":"playing"}} [Jun 3 22:06:14] DEBUG[28174] res_http_websocket.c: Writing websocket string of length 269 [Jun 3 22:06:14] DEBUG[28174] res_http_websocket.c: Writing websocket text frame, length 269 [Jun 3 22:06:14] DEBUG[28191] http.c: HTTP idle timeout or peer closed connection. [Jun 3 22:06:14] DEBUG[28191] http.c: HTTP closing session. Top level [Jun 3 22:06:14] DEBUG[28194] http.c: HTTP opening session. Top level [Jun 3 22:06:14] DEBUG[28194] http.c: HTTP Request URI is /ari/playbacks/2f530220-cd75-497e-a3be-0d2f820d83ba [Jun 3 22:06:14] DEBUG[28194] http.c: match request [ari/playbacks/2f530220-cd75-497e-a3be-0d2f820d83ba] with handler [httpstatus] len 10 [Jun 3 22:06:14] DEBUG[28194] http.c: match request [ari/playbacks/2f530220-cd75-497e-a3be-0d2f820d83ba] with handler [static] len 6 [Jun 3 22:06:14] DEBUG[28194] http.c: match request [ari/playbacks/2f530220-cd75-497e-a3be-0d2f820d83ba] with handler [ari] len 3 [Jun 3 22:06:14] DEBUG[28194] http.c: Match made with [ari] [Jun 3 22:06:14] DEBUG[28194] res_ari.c: Finding handler for playbacks [Jun 3 22:06:14] DEBUG[28194] res_ari.c: Checking channels [Jun 3 22:06:14] DEBUG[28194] res_ari.c: Checking asterisk [Jun 3 22:06:14] DEBUG[28194] res_ari.c: Checking deviceStates [Jun 3 22:06:14] DEBUG[28194] res_ari.c: Checking bridges [Jun 3 22:06:14] DEBUG[28194] res_ari.c: Checking events [Jun 3 22:06:14] DEBUG[28194] res_ari.c: Checking playbacks [Jun 3 22:06:14] DEBUG[28194] res_ari.c: Got it! [Jun 3 22:06:14] DEBUG[28194] res_ari.c: Finding handler for 2f530220-cd75-497e-a3be-0d2f820d83ba [Jun 3 22:06:14] DEBUG[28194] res_ari.c: Checking playbackId [Jun 3 22:06:14] DEBUG[28194] res_ari.c: Got it! [Jun 3 22:06:14] DEBUG[28194] res_ari.c: Examining ARI response: 204 No Content [Jun 3 22:06:14] DEBUG[28194] http.c: HTTP keeping session open. status_code:204 [Jun 3 22:06:14] DEBUG[28193][C-0000000f] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 3 22:06:14] DEBUG[28193][C-0000000f] channel.c: Hanging up channel 'Announcer/ARI-00000013;1' [Jun 3 22:06:14] DEBUG[28174] ari/ari_websockets.c: Examining ARI event (length 267): {"application":"4-call-6309ed62-29d7-11e6-9c63-defe000026b4-v3","type":"PlaybackFinished","playback":{"id":"2f530220-cd75-497e-a3be-0d2f820d83ba","media_uri":"tone:congestion","target_uri":"bridge:632d4320-29d7-11e6-895b-125fb2bca873","language":"en","state":"done"}} [Jun 3 22:06:14] DEBUG[28174] res_http_websocket.c: Writing websocket string of length 267 [Jun 3 22:06:14] DEBUG[28192] bridge_channel.c: Setting 0x7f4284081dd8(Announcer/ARI-00000013;2) state from:0 to:1 [Jun 3 22:06:14] DEBUG[28174] res_http_websocket.c: Writing websocket text frame, length 267 [Jun 3 22:06:14] DEBUG[28192] bridge_channel.c: Bridge 632d4320-29d7-11e6-895b-125fb2bca873: pulling 0x7f4284081dd8(Announcer/ARI-00000013;2) [Jun 3 22:06:14] VERBOSE[28192] bridge_channel.c: Channel Announcer/ARI-00000013;2 left 'simple_bridge' stasis-bridge <632d4320-29d7-11e6-895b-125fb2bca873> [Jun 3 22:06:14] DEBUG[28192] bridge_channel.c: Bridge 632d4320-29d7-11e6-895b-125fb2bca873: 0x7f4284081dd8(Announcer/ARI-00000013;2) is leaving simple_bridge technology [Jun 3 22:06:14] DEBUG[28192] bridge.c: Bridge technology softmix does not have any capabilities we want. [Jun 3 22:06:14] DEBUG[28192] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Jun 3 22:06:14] DEBUG[28192] bridge_native_rtp.c: Bridge '632d4320-29d7-11e6-895b-125fb2bca873' can not use native RTP bridge as two channels are required [Jun 3 22:06:14] DEBUG[28192] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Jun 3 22:06:14] DEBUG[28192] bridge.c: Chose bridge technology simple_bridge [Jun 3 22:06:14] DEBUG[28192] bridge.c: Bridge 632d4320-29d7-11e6-895b-125fb2bca873 is already using the new technology. [Jun 3 22:06:14] DEBUG[28192] channel.c: Hanging up channel 'Announcer/ARI-00000013;2' [Jun 3 22:06:14] DEBUG[18024] devicestate.c: No provider found, checking channel drivers for Announcer - ARI [Jun 3 22:06:14] DEBUG[18024] devicestate.c: Changing state for Announcer/ARI - state 0 (Unknown) [Jun 3 22:06:14] DEBUG[28194] http.c: HTTP idle timeout or peer closed connection. [Jun 3 22:06:14] DEBUG[28194] http.c: HTTP closing session. Top level [Jun 3 22:06:14] DEBUG[28195] http.c: HTTP opening session. Top level [Jun 3 22:06:14] DEBUG[28195] http.c: HTTP Request URI is /ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873/play [Jun 3 22:06:14] DEBUG[28195] http.c: match request [ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873/play] with handler [httpstatus] len 10 [Jun 3 22:06:14] DEBUG[28195] http.c: match request [ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873/play] with handler [static] len 6 [Jun 3 22:06:14] DEBUG[28195] http.c: match request [ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873/play] with handler [ari] len 3 [Jun 3 22:06:14] DEBUG[28195] http.c: Match made with [ari] [Jun 3 22:06:14] DEBUG[28195] http.c: HTTP consuming request body [Jun 3 22:06:14] DEBUG[28195] res_ari.c: Finding handler for bridges [Jun 3 22:06:14] DEBUG[28195] res_ari.c: Checking channels [Jun 3 22:06:14] DEBUG[28195] res_ari.c: Checking asterisk [Jun 3 22:06:14] DEBUG[28195] res_ari.c: Checking deviceStates [Jun 3 22:06:14] DEBUG[28195] res_ari.c: Checking bridges [Jun 3 22:06:14] DEBUG[28195] res_ari.c: Got it! [Jun 3 22:06:14] DEBUG[28195] res_ari.c: Finding handler for 632d4320-29d7-11e6-895b-125fb2bca873 [Jun 3 22:06:14] DEBUG[28195] res_ari.c: Checking bridgeId [Jun 3 22:06:14] DEBUG[28195] res_ari.c: Got it! [Jun 3 22:06:14] DEBUG[28195] res_ari.c: Finding handler for play [Jun 3 22:06:14] DEBUG[28195] res_ari.c: Checking addChannel [Jun 3 22:06:14] DEBUG[28195] res_ari.c: Checking removeChannel [Jun 3 22:06:14] DEBUG[28195] res_ari.c: Checking moh [Jun 3 22:06:14] DEBUG[28195] res_ari.c: Checking play [Jun 3 22:06:14] DEBUG[28195] res_ari.c: Got it! [Jun 3 22:06:14] DEBUG[28195] bridge_roles.c: Set role 'announcer' [Jun 3 22:06:14] DEBUG[28195] ari/resource_bridges.c: Created announcer channel 'Announcer/ARI-00000014;1' [Jun 3 22:06:14] DEBUG[28196] bridge_channel.c: Bridge 632d4320-29d7-11e6-895b-125fb2bca873: 0x7f42840a8a08(Announcer/ARI-00000014;2) is joining [Jun 3 22:06:14] DEBUG[28196] bridge_channel.c: Bridge 632d4320-29d7-11e6-895b-125fb2bca873: pushing 0x7f42840a8a08(Announcer/ARI-00000014;2) [Jun 3 22:06:14] DEBUG[28196] bridge_roles.c: Set role 'announcer' [Jun 3 22:06:14] VERBOSE[28196] bridge_channel.c: Channel Announcer/ARI-00000014;2 joined 'simple_bridge' stasis-bridge <632d4320-29d7-11e6-895b-125fb2bca873> [Jun 3 22:06:14] DEBUG[28196] bridge.c: Bridge technology softmix does not have any capabilities we want. [Jun 3 22:06:14] DEBUG[28196] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Jun 3 22:06:14] DEBUG[28196] bridge_native_rtp.c: Bridge '632d4320-29d7-11e6-895b-125fb2bca873' can not use native RTP bridge as it was forbidden while getting details [Jun 3 22:06:14] DEBUG[28196] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Jun 3 22:06:14] DEBUG[28196] bridge.c: Chose bridge technology simple_bridge [Jun 3 22:06:14] DEBUG[28196] bridge.c: Bridge 632d4320-29d7-11e6-895b-125fb2bca873 is already using the new technology. [Jun 3 22:06:14] DEBUG[28196] bridge.c: Bridge 632d4320-29d7-11e6-895b-125fb2bca873: 0x7f42840a8a08(Announcer/ARI-00000014;2) is joining simple_bridge technology [Jun 3 22:06:14] DEBUG[28189][C-0000000f] channel.c: PJSIP/sip-standard-0000000f: Dropping redundant connected line update "" <>. [Jun 3 22:06:14] DEBUG[28195] res_stasis_playback.c: i-0a321ef5a9fcf448c-1464991574.71: Sending play(tone:congestion) command [Jun 3 22:06:14] DEBUG[28174] ari/ari_websockets.c: Examining ARI event (length 513): {"channel":{"id":"i-0a321ef5a9fcf448c-1464991573.68","state":"Up","name":"PJSIP/sip-standard-0000000f","caller":{"name":"","number":"sip-standard"},"language":"en","connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"default","exten":"0000","priority":4},"creationtime":"2016-06-03T22:06:13.787+0000"},"application":"4-call-6309ed62-29d7-11e6-9c63-defe000026b4-v3","variable":"BRIDGEPEER","type":"ChannelVarset","value":"Announcer/ARI-00000014;2","timestamp":"2016-06-03T22:06:14.278+0000"} [Jun 3 22:06:14] DEBUG[28174] res_http_websocket.c: Writing websocket string of length 513 [Jun 3 22:06:14] DEBUG[28174] res_http_websocket.c: Writing websocket text frame, length 513 [Jun 3 22:06:14] DEBUG[28195] channel.c: Hanging up channel 'Announcer/ARI-00000014;1' [Jun 3 22:06:14] DEBUG[28195] res_ari.c: Examining ARI response: 500 Internal Server Error Content-type: application/json {"error":"Allocation failed"} [Jun 3 22:06:14] DEBUG[28195] http.c: HTTP keeping session open. status_code:500 [Jun 3 22:06:14] DEBUG[28196] bridge_channel.c: Setting 0x7f42840a8a08(Announcer/ARI-00000014;2) state from:0 to:1 [Jun 3 22:06:14] DEBUG[28196] bridge_channel.c: Bridge 632d4320-29d7-11e6-895b-125fb2bca873: pulling 0x7f42840a8a08(Announcer/ARI-00000014;2) [Jun 3 22:06:14] VERBOSE[28196] bridge_channel.c: Channel Announcer/ARI-00000014;2 left 'simple_bridge' stasis-bridge <632d4320-29d7-11e6-895b-125fb2bca873> [Jun 3 22:06:14] DEBUG[28196] bridge_channel.c: Bridge 632d4320-29d7-11e6-895b-125fb2bca873: 0x7f42840a8a08(Announcer/ARI-00000014;2) is leaving simple_bridge technology [Jun 3 22:06:14] DEBUG[28196] bridge.c: Bridge technology softmix does not have any capabilities we want. [Jun 3 22:06:14] DEBUG[28196] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Jun 3 22:06:14] DEBUG[28196] bridge_native_rtp.c: Bridge '632d4320-29d7-11e6-895b-125fb2bca873' can not use native RTP bridge as two channels are required [Jun 3 22:06:14] DEBUG[28196] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Jun 3 22:06:14] DEBUG[28196] bridge.c: Chose bridge technology simple_bridge [Jun 3 22:06:14] DEBUG[28196] bridge.c: Bridge 632d4320-29d7-11e6-895b-125fb2bca873 is already using the new technology. [Jun 3 22:06:14] DEBUG[28196] channel.c: Hanging up channel 'Announcer/ARI-00000014;2' [Jun 3 22:06:14] DEBUG[18024] devicestate.c: No provider found, checking channel drivers for Announcer - ARI [Jun 3 22:06:14] DEBUG[18024] devicestate.c: Changing state for Announcer/ARI - state 0 (Unknown) [Jun 3 22:06:14] DEBUG[28195] http.c: HTTP idle timeout or peer closed connection. [Jun 3 22:06:14] DEBUG[28195] http.c: HTTP closing session. Top level [Jun 3 22:06:14] DEBUG[28197] http.c: HTTP opening session. Top level [Jun 3 22:06:14] DEBUG[28197] http.c: HTTP Request URI is /ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873/play [Jun 3 22:06:14] DEBUG[28197] http.c: match request [ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873/play] with handler [httpstatus] len 10 [Jun 3 22:06:14] DEBUG[28197] http.c: match request [ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873/play] with handler [static] len 6 [Jun 3 22:06:14] DEBUG[28197] http.c: match request [ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873/play] with handler [ari] len 3 [Jun 3 22:06:14] DEBUG[28197] http.c: Match made with [ari] [Jun 3 22:06:14] DEBUG[28197] http.c: HTTP consuming request body [Jun 3 22:06:14] DEBUG[28197] res_ari.c: Finding handler for bridges [Jun 3 22:06:14] DEBUG[28197] res_ari.c: Checking channels [Jun 3 22:06:14] DEBUG[28197] res_ari.c: Checking asterisk [Jun 3 22:06:14] DEBUG[28197] res_ari.c: Checking deviceStates [Jun 3 22:06:14] DEBUG[28197] res_ari.c: Checking bridges [Jun 3 22:06:14] DEBUG[28197] res_ari.c: Got it! [Jun 3 22:06:14] DEBUG[28197] res_ari.c: Finding handler for 632d4320-29d7-11e6-895b-125fb2bca873 [Jun 3 22:06:14] DEBUG[28197] res_ari.c: Checking bridgeId [Jun 3 22:06:14] DEBUG[28197] res_ari.c: Got it! [Jun 3 22:06:14] DEBUG[28197] res_ari.c: Finding handler for play [Jun 3 22:06:14] DEBUG[28197] res_ari.c: Checking addChannel [Jun 3 22:06:14] DEBUG[28197] res_ari.c: Checking removeChannel [Jun 3 22:06:14] DEBUG[28197] res_ari.c: Checking moh [Jun 3 22:06:14] DEBUG[28197] res_ari.c: Checking play [Jun 3 22:06:14] DEBUG[28197] res_ari.c: Got it! [Jun 3 22:06:14] DEBUG[28197] bridge_roles.c: Set role 'announcer' [Jun 3 22:06:14] DEBUG[28197] ari/resource_bridges.c: Created announcer channel 'Announcer/ARI-00000015;1' [Jun 3 22:06:14] DEBUG[28198] bridge_channel.c: Bridge 632d4320-29d7-11e6-895b-125fb2bca873: 0x7f42840a8d58(Announcer/ARI-00000015;2) is joining [Jun 3 22:06:14] DEBUG[28198] bridge_channel.c: Bridge 632d4320-29d7-11e6-895b-125fb2bca873: pushing 0x7f42840a8d58(Announcer/ARI-00000015;2) [Jun 3 22:06:14] DEBUG[28198] bridge_roles.c: Set role 'announcer' [Jun 3 22:06:14] VERBOSE[28198] bridge_channel.c: Channel Announcer/ARI-00000015;2 joined 'simple_bridge' stasis-bridge <632d4320-29d7-11e6-895b-125fb2bca873> [Jun 3 22:06:14] DEBUG[28198] bridge.c: Bridge technology softmix does not have any capabilities we want. [Jun 3 22:06:14] DEBUG[28198] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Jun 3 22:06:14] DEBUG[28198] bridge_native_rtp.c: Bridge '632d4320-29d7-11e6-895b-125fb2bca873' can not use native RTP bridge as it was forbidden while getting details [Jun 3 22:06:14] DEBUG[28198] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Jun 3 22:06:14] DEBUG[28198] bridge.c: Chose bridge technology simple_bridge [Jun 3 22:06:14] DEBUG[28198] bridge.c: Bridge 632d4320-29d7-11e6-895b-125fb2bca873 is already using the new technology. [Jun 3 22:06:14] DEBUG[28198] bridge.c: Bridge 632d4320-29d7-11e6-895b-125fb2bca873: 0x7f42840a8d58(Announcer/ARI-00000015;2) is joining simple_bridge technology [Jun 3 22:06:14] DEBUG[28197] res_stasis_playback.c: i-0a321ef5a9fcf448c-1464991574.73: Sending play(tone:congestion) command [Jun 3 22:06:14] DEBUG[28197] channel.c: Hanging up channel 'Announcer/ARI-00000015;1' [Jun 3 22:06:14] DEBUG[28197] res_ari.c: Examining ARI response: 500 Internal Server Error Content-type: application/json {"error":"Allocation failed"} [Jun 3 22:06:14] DEBUG[28174] ari/ari_websockets.c: Examining ARI event (length 513): {"channel":{"id":"i-0a321ef5a9fcf448c-1464991573.68","state":"Up","name":"PJSIP/sip-standard-0000000f","caller":{"name":"","number":"sip-standard"},"language":"en","connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"default","exten":"0000","priority":4},"creationtime":"2016-06-03T22:06:13.787+0000"},"application":"4-call-6309ed62-29d7-11e6-9c63-defe000026b4-v3","variable":"BRIDGEPEER","type":"ChannelVarset","value":"Announcer/ARI-00000015;2","timestamp":"2016-06-03T22:06:14.281+0000"} [Jun 3 22:06:14] DEBUG[28174] res_http_websocket.c: Writing websocket string of length 513 [Jun 3 22:06:14] DEBUG[28174] res_http_websocket.c: Writing websocket text frame, length 513 [Jun 3 22:06:14] DEBUG[28197] http.c: HTTP keeping session open. status_code:500 [Jun 3 22:06:14] DEBUG[28198] bridge_channel.c: Setting 0x7f42840a8d58(Announcer/ARI-00000015;2) state from:0 to:1 [Jun 3 22:06:14] DEBUG[28189][C-0000000f] channel.c: PJSIP/sip-standard-0000000f: Dropping redundant connected line update "" <>. [Jun 3 22:06:14] DEBUG[28198] bridge_channel.c: Bridge 632d4320-29d7-11e6-895b-125fb2bca873: pulling 0x7f42840a8d58(Announcer/ARI-00000015;2) [Jun 3 22:06:14] VERBOSE[28198] bridge_channel.c: Channel Announcer/ARI-00000015;2 left 'simple_bridge' stasis-bridge <632d4320-29d7-11e6-895b-125fb2bca873> [Jun 3 22:06:14] DEBUG[28198] bridge_channel.c: Bridge 632d4320-29d7-11e6-895b-125fb2bca873: 0x7f42840a8d58(Announcer/ARI-00000015;2) is leaving simple_bridge technology [Jun 3 22:06:14] DEBUG[28198] bridge.c: Bridge technology softmix does not have any capabilities we want. [Jun 3 22:06:14] DEBUG[28198] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Jun 3 22:06:14] DEBUG[28198] bridge_native_rtp.c: Bridge '632d4320-29d7-11e6-895b-125fb2bca873' can not use native RTP bridge as two channels are required [Jun 3 22:06:14] DEBUG[28198] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Jun 3 22:06:14] DEBUG[28198] bridge.c: Chose bridge technology simple_bridge [Jun 3 22:06:14] DEBUG[28198] bridge.c: Bridge 632d4320-29d7-11e6-895b-125fb2bca873 is already using the new technology. [Jun 3 22:06:14] DEBUG[28198] channel.c: Hanging up channel 'Announcer/ARI-00000015;2' [Jun 3 22:06:14] DEBUG[18024] devicestate.c: No provider found, checking channel drivers for Announcer - ARI [Jun 3 22:06:14] DEBUG[18024] devicestate.c: Changing state for Announcer/ARI - state 0 (Unknown) [Jun 3 22:06:14] DEBUG[28197] http.c: HTTP idle timeout or peer closed connection. [Jun 3 22:06:14] DEBUG[28197] http.c: HTTP closing session. Top level [Jun 3 22:06:14] DEBUG[28189][C-0000000f] res_rtp_asterisk.c: 0x7f4298119640 -- Probation learning mode pass with source address REDACTED:16452 [Jun 3 22:06:14] VERBOSE[28189][C-0000000f] res_rtp_asterisk.c: 0x7f4298119640 -- Probation passed - setting RTP source address to REDACTED:16452 [Jun 3 22:06:14] DEBUG[18081] res_pjsip_registrar_expire.c: Woke up at 1464991574 Interval: 30 [Jun 3 22:06:14] DEBUG[18081] res_pjsip_registrar_expire.c: Expiring 0 contacts [Jun 3 22:06:16] DEBUG[18065] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Jun 3 22:06:16] DEBUG[18065] netsock2.c: Splitting 'ip-REDACTED' into... [Jun 3 22:06:16] DEBUG[18065] netsock2.c: ...host 'ip-REDACTED' and port ''. [Jun 3 22:06:16] DEBUG[18065] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Jun 3 22:06:16] DEBUG[18065] acl.c: Attached to given IP address [Jun 3 22:06:16] DEBUG[18094] netsock2.c: Splitting 'REDACTED:0' into... [Jun 3 22:06:16] DEBUG[18094] netsock2.c: ...host 'REDACTED' and port '0'. [Jun 3 22:06:16] DEBUG[18094] netsock2.c: Splitting 'REDACTED:16451' into... [Jun 3 22:06:16] DEBUG[18094] netsock2.c: ...host 'REDACTED' and port '16451'. [Jun 3 22:06:17] DEBUG[18047] netsock2.c: Splitting 'REDACTED:5060' into... [Jun 3 22:06:17] DEBUG[18047] netsock2.c: ...host 'REDACTED' and port '5060'. [Jun 3 22:06:17] DEBUG[18047] netsock2.c: Splitting '0.0.0.0:5060' into... [Jun 3 22:06:17] DEBUG[18047] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jun 3 22:06:17] DEBUG[18047] res_pjsip/pjsip_distributor.c: Searching for serializer on dialog dlg0x7f4298015f88 for (null) [Jun 3 22:06:17] DEBUG[18047] res_pjsip/pjsip_distributor.c: Found serializer pjsip/session/sip-standard-00000079 on dialog dlg0x7f4298015f88 [Jun 3 22:06:17] DEBUG[18048] netsock2.c: Splitting '0.0.0.0:5060' into... [Jun 3 22:06:17] DEBUG[18048] netsock2.c: ...host '0.0.0.0' and port '5060'. [Jun 3 22:06:17] DEBUG[18048] netsock2.c: Splitting 'REDACTED:5060' into... [Jun 3 22:06:17] DEBUG[18048] netsock2.c: ...host 'REDACTED' and port '5060'. [Jun 3 22:06:17] DEBUG[18048] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jun 3 22:06:17] DEBUG[18048] res_pjsip_session.c: The state change pertains to the endpoint 'sip-standard(PJSIP/sip-standard-0000000f)' [Jun 3 22:06:17] DEBUG[18048] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Jun 3 22:06:17] DEBUG[18048] res_pjsip_session.c: The UAS BYE transaction involved in this state change is 0x7f429800d618 [Jun 3 22:06:17] DEBUG[18048] res_pjsip_session.c: The current transaction state is Completed [Jun 3 22:06:17] DEBUG[18048] res_pjsip_session.c: The transaction state change event is TX_MSG [Jun 3 22:06:17] DEBUG[18048] res_pjsip_session.c: The current inv state is CONFIRMED [Jun 3 22:06:17] DEBUG[18048] res_pjsip_session.c: Sending response [Jun 3 22:06:17] DEBUG[18048] res_pjsip_session.c: Method is BYE, Response is 200 OK [Jun 3 22:06:17] DEBUG[18048] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Jun 3 22:06:17] DEBUG[18048] res_pjsip_session.c: The state change pertains to the endpoint 'sip-standard(PJSIP/sip-standard-0000000f)' [Jun 3 22:06:17] DEBUG[18048] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Jun 3 22:06:17] DEBUG[18048] res_pjsip_session.c: There is no transaction involved in this state change [Jun 3 22:06:17] DEBUG[18048] res_pjsip_session.c: The current inv state is DISCONNCTD [Jun 3 22:06:17] DEBUG[18048] res_pjsip_session.c: Source of transaction state change is RX_MSG [Jun 3 22:06:17] DEBUG[18048] res_pjsip_session.c: Received request [Jun 3 22:06:17] DEBUG[18048] res_pjsip_session.c: Method is BYE [Jun 3 22:06:17] DEBUG[18048] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jun 3 22:06:17] DEBUG[18048] res_pjsip_session.c: The state change pertains to the endpoint 'sip-standard(PJSIP/sip-standard-0000000f)' [Jun 3 22:06:17] DEBUG[18048] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Jun 3 22:06:17] DEBUG[18048] res_pjsip_session.c: The UAS BYE transaction involved in this state change is 0x7f429800d618 [Jun 3 22:06:17] DEBUG[18048] res_pjsip_session.c: The current transaction state is Completed [Jun 3 22:06:17] DEBUG[18048] res_pjsip_session.c: The transaction state change event is RX_MSG [Jun 3 22:06:17] DEBUG[18048] res_pjsip_session.c: The current inv state is DISCONNCTD [Jun 3 22:06:17] DEBUG[28189][C-0000000f] bridge_channel.c: Setting 0x7f429409f6a8(PJSIP/sip-standard-0000000f) state from:0 to:1 [Jun 3 22:06:17] DEBUG[28174] ari/ari_websockets.c: Examining ARI event (length 472): {"cause":16,"application":"4-call-6309ed62-29d7-11e6-9c63-defe000026b4-v3","type":"ChannelHangupRequest","timestamp":"2016-06-03T22:06:17.918+0000","channel":{"id":"i-0a321ef5a9fcf448c-1464991573.68","state":"Up","name":"PJSIP/sip-standard-0000000f","caller":{"name":"","number":"sip-standard"},"language":"en","connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"default","exten":"0000","priority":4},"creationtime":"2016-06-03T22:06:13.787+0000"}} [Jun 3 22:06:17] DEBUG[28174] res_http_websocket.c: Writing websocket string of length 472 [Jun 3 22:06:17] DEBUG[28174] res_http_websocket.c: Writing websocket text frame, length 472 [Jun 3 22:06:17] DEBUG[28189][C-0000000f] bridge_channel.c: Bridge 632d4320-29d7-11e6-895b-125fb2bca873: pulling 0x7f429409f6a8(PJSIP/sip-standard-0000000f) [Jun 3 22:06:17] VERBOSE[28189][C-0000000f] bridge_channel.c: Channel PJSIP/sip-standard-0000000f left 'simple_bridge' stasis-bridge <632d4320-29d7-11e6-895b-125fb2bca873> [Jun 3 22:06:17] DEBUG[28189][C-0000000f] bridge_channel.c: Bridge 632d4320-29d7-11e6-895b-125fb2bca873: 0x7f429409f6a8(PJSIP/sip-standard-0000000f) is leaving simple_bridge technology [Jun 3 22:06:17] DEBUG[28174] ari/ari_websockets.c: Examining ARI event (length 489): {"channel":{"id":"i-0a321ef5a9fcf448c-1464991573.68","state":"Up","name":"PJSIP/sip-standard-0000000f","caller":{"name":"","number":"sip-standard"},"language":"en","connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"default","exten":"0000","priority":4},"creationtime":"2016-06-03T22:06:13.787+0000"},"application":"4-call-6309ed62-29d7-11e6-9c63-defe000026b4-v3","variable":"BRIDGEPEER","type":"ChannelVarset","value":"","timestamp":"2016-06-03T22:06:17.918+0000"} [Jun 3 22:06:17] DEBUG[28174] res_http_websocket.c: Writing websocket string of length 489 [Jun 3 22:06:17] DEBUG[28174] res_http_websocket.c: Writing websocket text frame, length 489 [Jun 3 22:06:17] DEBUG[18036] cdr.c: Finalized CDR for PJSIP/sip-standard-0000000f - start 1464991573.788020 answer 1464991574.190497 end 1464991577.919131 dispo ANSWERED [Jun 3 22:06:17] DEBUG[28174] ari/ari_websockets.c: Examining ARI event (length 639): {"application":"4-call-6309ed62-29d7-11e6-9c63-defe000026b4-v3","type":"ChannelLeftBridge","bridge":{"id":"632d4320-29d7-11e6-895b-125fb2bca873","channels":[],"name":"default","technology":"simple_bridge","bridge_class":"stasis","creator":"Stasis","bridge_type":"mixing"},"timestamp":"2016-06-03T22:06:17.919+0000","channel":{"id":"i-0a321ef5a9fcf448c-1464991573.68","state":"Up","name":"PJSIP/sip-standard-0000000f","caller":{"name":"","number":"sip-standard"},"language":"en","connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"default","exten":"0000","priority":4},"creationtime":"2016-06-03T22:06:13.787+0000"}} [Jun 3 22:06:17] DEBUG[28174] res_http_websocket.c: Writing websocket string of length 639 [Jun 3 22:06:17] DEBUG[28174] res_http_websocket.c: Writing websocket text frame, length 639 [Jun 3 22:06:17] DEBUG[28189][C-0000000f] bridge.c: Bridge technology softmix does not have any capabilities we want. [Jun 3 22:06:17] DEBUG[28189][C-0000000f] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Jun 3 22:06:17] DEBUG[28189][C-0000000f] bridge_native_rtp.c: Bridge '632d4320-29d7-11e6-895b-125fb2bca873' can not use native RTP bridge as two channels are required [Jun 3 22:06:17] DEBUG[28189][C-0000000f] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Jun 3 22:06:17] DEBUG[28189][C-0000000f] bridge.c: Chose bridge technology simple_bridge [Jun 3 22:06:17] DEBUG[28189][C-0000000f] bridge.c: Bridge 632d4320-29d7-11e6-895b-125fb2bca873 is already using the new technology. [Jun 3 22:06:17] DEBUG[28189][C-0000000f] bridge_channel.c: Bridge is returning 0x7f429409f6a8(PJSIP/sip-standard-0000000f) to read format ulaw [Jun 3 22:06:17] DEBUG[28189][C-0000000f] channel.c: Channel PJSIP/sip-standard-0000000f setting read format path: ulaw -> ulaw [Jun 3 22:06:17] DEBUG[28189][C-0000000f] bridge_channel.c: Bridge is returning 0x7f429409f6a8(PJSIP/sip-standard-0000000f) to write format ulaw [Jun 3 22:06:17] DEBUG[28189][C-0000000f] channel.c: Channel PJSIP/sip-standard-0000000f setting write format path: ulaw -> ulaw [Jun 3 22:06:17] DEBUG[28189][C-0000000f] stasis/control.c: i-0a321ef5a9fcf448c-1464991573.68, 632d4320-29d7-11e6-895b-125fb2bca873: Channel leaving bridge [Jun 3 22:06:17] DEBUG[28189][C-0000000f] stasis/app.c: bridge '632d4320-29d7-11e6-895b-125fb2bca873': is 1 interested in 4-call-6309ed62-29d7-11e6-9c63-defe000026b4-v3 [Jun 3 22:06:17] DEBUG[28189][C-0000000f] stasis/control.c: reason: Channel was departed from bridge [Jun 3 22:06:17] DEBUG[28169][C-0000000f] stasis/control.c: i-0a321ef5a9fcf448c-1464991573.68: Channel departing bridge [Jun 3 22:06:17] DEBUG[28169][C-0000000f] bridge.c: Waiting for 0x7f429409f6a8(PJSIP/sip-standard-0000000f) bridge thread to die. [Jun 3 22:06:17] DEBUG[28169][C-0000000f] stasis/app.c: App '4-call-6309ed62-29d7-11e6-9c63-defe000026b4-v3' not subscribed to bridge '__AST_BRIDGE_ALL_TOPIC' [Jun 3 22:06:17] DEBUG[28169][C-0000000f] stasis/app.c: channel 'i-0a321ef5a9fcf448c-1464991573.68': is 0 interested in 4-call-6309ed62-29d7-11e6-9c63-defe000026b4-v3 [Jun 3 22:06:17] DEBUG[28169][C-0000000f] stasis/app.c: channel 'i-0a321ef5a9fcf448c-1464991573.68' unsubscribed from 4-call-6309ed62-29d7-11e6-9c63-defe000026b4-v3 [Jun 3 22:06:17] DEBUG[28169][C-0000000f] pbx.c: Extension 0000, priority 4 returned normally even though call was hung up [Jun 3 22:06:17] DEBUG[28169][C-0000000f] channel.c: Soft-Hanging (0x10) up channel 'PJSIP/sip-standard-0000000f' [Jun 3 22:06:17] DEBUG[28169][C-0000000f] channel.c: Hanging up channel 'PJSIP/sip-standard-0000000f' [Jun 3 22:06:17] DEBUG[28169][C-0000000f] chan_pjsip.c: AST hangup cause 16 (no match found in PJSIP) [Jun 3 22:06:17] DEBUG[28174] ari/ari_websockets.c: Examining ARI event (length 450): {"application":"4-call-6309ed62-29d7-11e6-9c63-defe000026b4-v3","type":"StasisEnd","timestamp":"2016-06-03T22:06:17.919+0000","channel":{"id":"i-0a321ef5a9fcf448c-1464991573.68","state":"Up","name":"PJSIP/sip-standard-0000000f","caller":{"name":"","number":"sip-standard"},"language":"en","connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"default","exten":"0000","priority":4},"creationtime":"2016-06-03T22:06:13.787+0000"}} [Jun 3 22:06:17] DEBUG[28174] res_http_websocket.c: Writing websocket string of length 450 [Jun 3 22:06:17] DEBUG[28174] res_http_websocket.c: Writing websocket text frame, length 450 [Jun 3 22:06:17] DEBUG[18024] devicestate.c: No provider found, checking channel drivers for PJSIP - sip-standard [Jun 3 22:06:17] DEBUG[18024] devicestate.c: Changing state for PJSIP/sip-standard - state 1 (Not in use) [Jun 3 22:06:17] DEBUG[28204] http.c: HTTP opening session. Top level [Jun 3 22:06:17] DEBUG[28204] http.c: HTTP Request URI is /ari/channels/i-0a321ef5a9fcf448c-1464991573.68 [Jun 3 22:06:17] DEBUG[28204] http.c: match request [ari/channels/i-0a321ef5a9fcf448c-1464991573.68] with handler [httpstatus] len 10 [Jun 3 22:06:17] DEBUG[28204] http.c: match request [ari/channels/i-0a321ef5a9fcf448c-1464991573.68] with handler [static] len 6 [Jun 3 22:06:17] DEBUG[28204] http.c: match request [ari/channels/i-0a321ef5a9fcf448c-1464991573.68] with handler [ari] len 3 [Jun 3 22:06:17] DEBUG[28204] http.c: Match made with [ari] [Jun 3 22:06:17] DEBUG[28204] res_ari.c: Finding handler for channels [Jun 3 22:06:17] DEBUG[28204] res_ari.c: Checking channels [Jun 3 22:06:17] DEBUG[28204] res_ari.c: Got it! [Jun 3 22:06:17] DEBUG[28204] res_ari.c: Finding handler for i-0a321ef5a9fcf448c-1464991573.68 [Jun 3 22:06:17] DEBUG[28204] res_ari.c: Checking channelId [Jun 3 22:06:17] DEBUG[28204] res_ari.c: Got it! [Jun 3 22:06:17] DEBUG[28204] res_ari.c: Examining ARI response: 404 Not Found Content-type: application/json {"message":"Channel not found"} [Jun 3 22:06:17] DEBUG[28204] http.c: HTTP keeping session open. status_code:404 [Jun 3 22:06:17] DEBUG[28204] http.c: HTTP idle timeout or peer closed connection. [Jun 3 22:06:17] DEBUG[28204] http.c: HTTP closing session. Top level [Jun 3 22:06:17] DEBUG[28205] http.c: HTTP opening session. Top level [Jun 3 22:06:17] DEBUG[28205] http.c: HTTP Request URI is /ari/channels/i-0a321ef5a9fcf448c-1464991573.68 [Jun 3 22:06:17] DEBUG[28205] http.c: match request [ari/channels/i-0a321ef5a9fcf448c-1464991573.68] with handler [httpstatus] len 10 [Jun 3 22:06:17] DEBUG[28205] http.c: match request [ari/channels/i-0a321ef5a9fcf448c-1464991573.68] with handler [static] len 6 [Jun 3 22:06:17] DEBUG[28205] http.c: match request [ari/channels/i-0a321ef5a9fcf448c-1464991573.68] with handler [ari] len 3 [Jun 3 22:06:17] DEBUG[28205] http.c: Match made with [ari] [Jun 3 22:06:17] DEBUG[28205] res_ari.c: Finding handler for channels [Jun 3 22:06:17] DEBUG[28205] res_ari.c: Checking channels [Jun 3 22:06:17] DEBUG[28205] res_ari.c: Got it! [Jun 3 22:06:17] DEBUG[28205] res_ari.c: Finding handler for i-0a321ef5a9fcf448c-1464991573.68 [Jun 3 22:06:17] DEBUG[28205] res_ari.c: Checking channelId [Jun 3 22:06:17] DEBUG[28205] res_ari.c: Got it! [Jun 3 22:06:17] DEBUG[28205] res_ari.c: Examining ARI response: 404 Not Found Content-type: application/json {"message":"Channel not found"} [Jun 3 22:06:17] DEBUG[28205] http.c: HTTP keeping session open. status_code:404 [Jun 3 22:06:17] DEBUG[28205] http.c: HTTP idle timeout or peer closed connection. [Jun 3 22:06:17] DEBUG[28205] http.c: HTTP closing session. Top level [Jun 3 22:06:17] DEBUG[28206] http.c: HTTP opening session. Top level [Jun 3 22:06:17] DEBUG[28206] http.c: HTTP Request URI is /ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873 [Jun 3 22:06:17] DEBUG[28206] http.c: match request [ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873] with handler [httpstatus] len 10 [Jun 3 22:06:17] DEBUG[28206] http.c: match request [ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873] with handler [static] len 6 [Jun 3 22:06:17] DEBUG[28206] http.c: match request [ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873] with handler [ari] len 3 [Jun 3 22:06:17] DEBUG[28206] http.c: Match made with [ari] [Jun 3 22:06:17] DEBUG[28206] res_ari.c: Finding handler for bridges [Jun 3 22:06:17] DEBUG[28206] res_ari.c: Checking channels [Jun 3 22:06:17] DEBUG[28206] res_ari.c: Checking asterisk [Jun 3 22:06:17] DEBUG[28206] res_ari.c: Checking deviceStates [Jun 3 22:06:17] DEBUG[28206] res_ari.c: Checking bridges [Jun 3 22:06:17] DEBUG[28206] res_ari.c: Got it! [Jun 3 22:06:17] DEBUG[28206] res_ari.c: Finding handler for 632d4320-29d7-11e6-895b-125fb2bca873 [Jun 3 22:06:17] DEBUG[28206] res_ari.c: Checking bridgeId [Jun 3 22:06:17] DEBUG[28206] res_ari.c: Got it! [Jun 3 22:06:17] DEBUG[28206] res_ari.c: Examining ARI response: 200 OK Content-type: application/json {"id":"632d4320-29d7-11e6-895b-125fb2bca873","channels":[],"name":"default","technology":"simple_bridge","bridge_class":"stasis","creator":"Stasis","bridge_type":"mixing"} [Jun 3 22:06:17] DEBUG[28206] http.c: HTTP keeping session open. status_code:200 [Jun 3 22:06:17] DEBUG[28206] http.c: HTTP idle timeout or peer closed connection. [Jun 3 22:06:17] DEBUG[28206] http.c: HTTP closing session. Top level [Jun 3 22:06:17] DEBUG[28207] http.c: HTTP opening session. Top level [Jun 3 22:06:17] DEBUG[28207] http.c: HTTP Request URI is /ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873 [Jun 3 22:06:17] DEBUG[28207] http.c: match request [ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873] with handler [httpstatus] len 10 [Jun 3 22:06:17] DEBUG[28207] http.c: match request [ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873] with handler [static] len 6 [Jun 3 22:06:17] DEBUG[28207] http.c: match request [ari/bridges/632d4320-29d7-11e6-895b-125fb2bca873] with handler [ari] len 3 [Jun 3 22:06:17] DEBUG[28207] http.c: Match made with [ari] [Jun 3 22:06:17] DEBUG[28207] res_ari.c: Finding handler for bridges [Jun 3 22:06:17] DEBUG[28207] res_ari.c: Checking channels [Jun 3 22:06:17] DEBUG[28207] res_ari.c: Checking asterisk [Jun 3 22:06:17] DEBUG[28207] res_ari.c: Checking deviceStates [Jun 3 22:06:17] DEBUG[28207] res_ari.c: Checking bridges [Jun 3 22:06:17] DEBUG[28207] res_ari.c: Got it! [Jun 3 22:06:17] DEBUG[28207] res_ari.c: Finding handler for 632d4320-29d7-11e6-895b-125fb2bca873 [Jun 3 22:06:17] DEBUG[28207] res_ari.c: Checking bridgeId [Jun 3 22:06:17] DEBUG[28207] res_ari.c: Got it! [Jun 3 22:06:17] DEBUG[28207] bridge.c: Bridge 632d4320-29d7-11e6-895b-125fb2bca873: telling all channels to leave the party [Jun 3 22:06:17] DEBUG[28207] bridge.c: Bridge 632d4320-29d7-11e6-895b-125fb2bca873: dissolving bridge with cause 16(Normal Clearing) [Jun 3 22:06:17] DEBUG[28207] bridge.c: Bridge 632d4320-29d7-11e6-895b-125fb2bca873: queueing action type:13 sub:1001 [Jun 3 22:06:17] DEBUG[28207] res_ari.c: Examining ARI response: 204 No Content [Jun 3 22:06:17] DEBUG[28207] http.c: HTTP keeping session open. status_code:204 [Jun 3 22:06:17] DEBUG[18023][C-0000000f] bridge.c: Bridge 632d4320-29d7-11e6-895b-125fb2bca873: actually destroying stasis bridge, nobody wants it anymore [Jun 3 22:06:17] DEBUG[18023][C-0000000f] bridge.c: Bridge 632d4320-29d7-11e6-895b-125fb2bca873: calling stasis bridge destructor [Jun 3 22:06:17] DEBUG[18023][C-0000000f] bridge.c: Bridge 632d4320-29d7-11e6-895b-125fb2bca873: calling simple_bridge technology stop [Jun 3 22:06:17] DEBUG[18023][C-0000000f] bridge.c: Bridge 632d4320-29d7-11e6-895b-125fb2bca873: calling simple_bridge technology destructor [Jun 3 22:06:17] DEBUG[28174] ari/ari_websockets.c: Examining ARI event (length 313): {"application":"4-call-6309ed62-29d7-11e6-9c63-defe000026b4-v3","type":"BridgeDestroyed","bridge":{"id":"632d4320-29d7-11e6-895b-125fb2bca873","channels":[],"name":"default","technology":"simple_bridge","bridge_class":"stasis","creator":"Stasis","bridge_type":"mixing"},"timestamp":"2016-06-03T22:06:17.928+0000"} [Jun 3 22:06:17] DEBUG[28174] res_http_websocket.c: Writing websocket string of length 313 [Jun 3 22:06:17] D