[Feb 22 12:49:42] DEBUG[17872] stasis/app.c: Endpoint 'ALL' is 1 interested in call-control [Feb 22 12:49:42] VERBOSE[17872] res_http_websocket.c: WebSocket connection from '10.16.31.195:32491' for protocol '' accepted using version '13' [Feb 22 12:49:42] DEBUG[17872] ari/resource_events.c: /events WebSocket established [Feb 22 12:49:53] DEBUG[17675] chan_sip.c: = Looking for Call ID: 150721772-0-1520124388@199.68.168.21 (Checking From) --From tag sansay503340733rdb1068 --To-tag [Feb 22 12:49:53] DEBUG[17675] acl.c: For destination '199.68.168.27', our source address is '199.180.211.19'. [Feb 22 12:49:53] DEBUG[17675] chan_sip.c: Setting AST_TRANSPORT_UDP with address 199.180.211.19:5060 [Feb 22 12:49:53] DEBUG[17675] netsock2.c: Splitting '199.68.168.27:5060' into... [Feb 22 12:49:53] DEBUG[17675] netsock2.c: ...host '199.68.168.27' and port '5060'. [Feb 22 12:49:53] DEBUG[17675] chan_sip.c: Allocating new SIP dialog for 150721772-0-1520124388@199.68.168.21 - INVITE (No RTP) [Feb 22 12:49:53] DEBUG[17675][C-00000001] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Feb 22 12:49:53] DEBUG[17675][C-00000001] sip/reqresp_parser.c: Begin: parsing SIP "Supported: timer,100rel,replaces" [Feb 22 12:49:53] DEBUG[17675][C-00000001] sip/reqresp_parser.c: Found SIP option: -timer- [Feb 22 12:49:53] DEBUG[17675][C-00000001] sip/reqresp_parser.c: Matched SIP option: timer [Feb 22 12:49:53] DEBUG[17675][C-00000001] sip/reqresp_parser.c: Found SIP option: -100rel- [Feb 22 12:49:53] DEBUG[17675][C-00000001] sip/reqresp_parser.c: Matched SIP option: 100rel [Feb 22 12:49:53] DEBUG[17675][C-00000001] sip/reqresp_parser.c: Found SIP option: -replaces- [Feb 22 12:49:53] DEBUG[17675][C-00000001] sip/reqresp_parser.c: Matched SIP option: replaces [Feb 22 12:49:53] DEBUG[17675][C-00000001] netsock2.c: Splitting '199.68.168.27:5060' into... [Feb 22 12:49:53] DEBUG[17675][C-00000001] netsock2.c: ...host '199.68.168.27' and port '5060'. [Feb 22 12:49:53] DEBUG[17675][C-00000001] netsock2.c: Splitting '199.68.168.27' into... [Feb 22 12:49:53] DEBUG[17675][C-00000001] netsock2.c: ...host '199.68.168.27' and port ''. [Feb 22 12:49:53] DEBUG[17675][C-00000001] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f7958009718' [Feb 22 12:49:53] DEBUG[17675][C-00000001] res_rtp_asterisk.c: Allocated port 14306 for RTP instance '0x7f7958009718' [Feb 22 12:49:53] DEBUG[17675][C-00000001] res_rtp_asterisk.c: Creating ICE session 0.0.0.0:14306 (14306) for RTP instance '0x7f7958009718' [Feb 22 12:49:53] DEBUG[17675][C-00000001] netsock2.c: Splitting '199.180.211.19' into... [Feb 22 12:49:53] DEBUG[17675][C-00000001] netsock2.c: ...host '199.180.211.19' and port ''. [Feb 22 12:49:53] DEBUG[17675][C-00000001] netsock2.c: Splitting '199.180.211.19' into... [Feb 22 12:49:53] DEBUG[17675][C-00000001] netsock2.c: ...host '199.180.211.19' and port ''. [Feb 22 12:49:53] DEBUG[17675][C-00000001] netsock2.c: Splitting '172.17.0.1' into... [Feb 22 12:49:53] DEBUG[17675][C-00000001] netsock2.c: ...host '172.17.0.1' and port ''. [Feb 22 12:49:53] DEBUG[17675][C-00000001] netsock2.c: Splitting '172.17.0.1' into... [Feb 22 12:49:53] DEBUG[17675][C-00000001] netsock2.c: ...host '172.17.0.1' and port ''. [Feb 22 12:49:53] DEBUG[17675][C-00000001] rtp_engine.c: RTP instance '0x7f7958009718' is setup and ready to go [Feb 22 12:49:53] DEBUG[17675][C-00000001] netsock2.c: Splitting 'pod09-asterisk02.dev-core.fvscloud.com' into... [Feb 22 12:49:53] DEBUG[17675][C-00000001] netsock2.c: ...host 'pod09-asterisk02.dev-core.fvscloud.com' and port ''. [Feb 22 12:49:53] DEBUG[17675][C-00000001] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f7958009718' [Feb 22 12:49:53] VERBOSE[17675][C-00000001] netsock2.c: Using SIP RTP CoS mark 5 [Feb 22 12:49:53] DEBUG[17675][C-00000001] chan_sip.c: Setting NAT on RTP to On [Feb 22 12:49:53] DEBUG[17675][C-00000001] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Feb 22 12:49:53] DEBUG[17675][C-00000001] chan_sip.c: Processing session-level SDP o=Sansay-VSXi 188 1 IN IP4 199.68.168.27... OK. [Feb 22 12:49:53] DEBUG[17675][C-00000001] chan_sip.c: Processing session-level SDP s=Session Controller... UNSUPPORTED OR FAILED. [Feb 22 12:49:53] DEBUG[17675][C-00000001] netsock2.c: Splitting '67.231.1.91' into... [Feb 22 12:49:53] DEBUG[17675][C-00000001] netsock2.c: ...host '67.231.1.91' and port ''. [Feb 22 12:49:53] DEBUG[17675][C-00000001] chan_sip.c: Processing session-level SDP c=IN IP4 67.231.1.91... OK. [Feb 22 12:49:53] DEBUG[17675][C-00000001] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Feb 22 12:49:53] DEBUG[17675][C-00000001] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7f79381f9a00 [Feb 22 12:49:53] DEBUG[17675][C-00000001] rtp_engine.c: Setting tx payload type 18 based on m type on 0x7f79381f9a00 [Feb 22 12:49:53] DEBUG[17675][C-00000001] rtp_engine.c: Setting tx payload type 101 based on m type on 0x7f79381f9a00 [Feb 22 12:49:53] DEBUG[17675][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Feb 22 12:49:53] DEBUG[17675][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK. [Feb 22 12:49:53] DEBUG[17675][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=fmtp:18 annexb=no... OK. [Feb 22 12:49:53] DEBUG[17675][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Feb 22 12:49:53] DEBUG[17675][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED OR FAILED. [Feb 22 12:49:53] DEBUG[17675][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Feb 22 12:49:53] DEBUG[17675][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK. [Feb 22 12:49:53] DEBUG[17675][C-00000001] rtp_engine.c: Crossover copying tx to rx payload mapping 0 (0x7f7958008e70) from 0x7f79381f9a00 to 0x7f79381f9a00 [Feb 22 12:49:53] DEBUG[17675][C-00000001] rtp_engine.c: Crossover copying tx to rx payload mapping 18 (0x7f7958006880) from 0x7f79381f9a00 to 0x7f79381f9a00 [Feb 22 12:49:53] DEBUG[17675][C-00000001] rtp_engine.c: Crossover copying tx to rx payload mapping 101 (0x1421ba0) from 0x7f79381f9a00 to 0x7f79381f9a00 [Feb 22 12:49:53] DEBUG[17675][C-00000001] acl.c: For destination '67.231.1.91', our source address is '199.180.211.19'. [Feb 22 12:49:53] DEBUG[17675][C-00000001] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f7958009718' [Feb 22 12:49:53] VERBOSE[17675][C-00000001] res_rtp_asterisk.c: 0x7f795800a670 -- Strict RTP learning after remote address set to: 67.231.1.91:25768 [Feb 22 12:49:53] DEBUG[17675][C-00000001] rtp_engine.c: Copying rx payload mapping 0 (0x7f7958008e70) from 0x7f79381f9a00 to 0x7f79580098e0 [Feb 22 12:49:53] DEBUG[17675][C-00000001] rtp_engine.c: Copying rx payload mapping 18 (0x7f7958006880) from 0x7f79381f9a00 to 0x7f79580098e0 [Feb 22 12:49:53] DEBUG[17675][C-00000001] rtp_engine.c: Copying rx payload mapping 101 (0x1421ba0) from 0x7f79381f9a00 to 0x7f79580098e0 [Feb 22 12:49:53] DEBUG[17675][C-00000001] rtp_engine.c: Copying tx payload mapping 0 (0x7f7958008e70) from 0x7f79381f9a00 to 0x7f79580098e0 [Feb 22 12:49:53] DEBUG[17675][C-00000001] rtp_engine.c: Copying tx payload mapping 18 (0x7f7958006880) from 0x7f79381f9a00 to 0x7f79580098e0 [Feb 22 12:49:53] DEBUG[17675][C-00000001] rtp_engine.c: Copying tx payload mapping 101 (0x1421ba0) from 0x7f79381f9a00 to 0x7f79580098e0 [Feb 22 12:49:53] DEBUG[17675][C-00000001] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7f7958009718' [Feb 22 12:49:53] DEBUG[17675][C-00000001] chan_sip.c: We're settling with these formats: (ulaw) [Feb 22 12:49:53] DEBUG[17675][C-00000001] chan_sip.c: Checking SIP call limits for device [Feb 22 12:49:53] DEBUG[17675][C-00000001] chan_sip.c: Updating call counter for incoming call [Feb 22 12:49:53] DEBUG[17675][C-00000001] netsock2.c: Splitting '199.180.211.19:5060' into... [Feb 22 12:49:53] DEBUG[17675][C-00000001] netsock2.c: ...host '199.180.211.19' and port ''. [Feb 22 12:49:53] DEBUG[17675][C-00000001] netsock2.c: Splitting '199.68.168.27' into... [Feb 22 12:49:53] DEBUG[17675][C-00000001] netsock2.c: ...host '199.68.168.27' and port ''. [Feb 22 12:49:53] DEBUG[17675][C-00000001] chan_sip.c: Incoming INVITE with 'timer' option supported [Feb 22 12:49:53] DEBUG[17675][C-00000001] chan_sip.c: INVITE also has "Session-Expires" header. [Feb 22 12:49:53] DEBUG[17675][C-00000001] chan_sip.c: Session-Expires: 600 [Feb 22 12:49:53] DEBUG[17675][C-00000001] chan_sip.c: Refresher: UAC [Feb 22 12:49:53] DEBUG[17675][C-00000001] chan_sip.c: INVITE also has "Min-SE" header. [Feb 22 12:49:53] DEBUG[17675][C-00000001] chan_sip.c: Received Min-SE: 90 [Feb 22 12:49:53] DEBUG[17675][C-00000001] channel.c: Channel 0x7f7958015658 'SIP/199.68.168.27-00000000' allocated [Feb 22 12:49:53] DEBUG[17675][C-00000001] chan_sip.c: *** Our native formats are (ulaw) [Feb 22 12:49:53] DEBUG[17675][C-00000001] chan_sip.c: *** Joint capabilities are (ulaw) [Feb 22 12:49:53] DEBUG[17675][C-00000001] chan_sip.c: *** Our capabilities are (ulaw) [Feb 22 12:49:53] DEBUG[17675][C-00000001] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw [Feb 22 12:49:53] DEBUG[17675][C-00000001] chan_sip.c: This channel will not be able to handle video. [Feb 22 12:49:53] DEBUG[17675][C-00000001] sip/route.c: sip_route_process_header: [Feb 22 12:49:53] DEBUG[17675][C-00000001] chan_sip.c: SIP/199.68.168.27-00000000: New call is still down.... Trying... [Feb 22 12:49:53] DEBUG[17675][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 199.68.168.27:5060 [Feb 22 12:49:53] DEBUG[17663] devicestate.c: No provider found, checking channel drivers for SIP - 199.68.168.27 [Feb 22 12:49:53] DEBUG[17663] chan_sip.c: Checking device state for peer 199.68.168.27 [Feb 22 12:49:53] DEBUG[17663] devicestate.c: Changing state for SIP/199.68.168.27 - state 4 (Invalid) [Feb 22 12:49:53] DEBUG[17964][C-00000001] pbx_variables.c: Result of 'AbsoluteTimeout' is '14460' [Feb 22 12:49:53] DEBUG[17964][C-00000001] pbx.c: Launching 'Set' [Feb 22 12:49:53] VERBOSE[17964][C-00000001] pbx.c: Executing [17608714288@pstn:1] Set("SIP/199.68.168.27-00000000", "TIMEOUT(absolute)=14460") in new stack [Feb 22 12:49:53] DEBUG[17874] res_http_websocket.c: Writing websocket string of length 588 [Feb 22 12:49:53] DEBUG[17874] res_http_websocket.c: Writing websocket text frame, length 588 [Feb 22 12:49:53] VERBOSE[17964][C-00000001] func_timeout.c: Channel will hangup at 2018-02-22 16:50:53.803 PST. [Feb 22 12:49:53] DEBUG[17964][C-00000001] pbx.c: Launching 'Stasis' [Feb 22 12:49:53] VERBOSE[17964][C-00000001] pbx.c: Executing [17608714288@pstn:2] Stasis("SIP/199.68.168.27-00000000", "call-control") in new stack [Feb 22 12:49:53] DEBUG[17874] res_http_websocket.c: Writing websocket string of length 661 [Feb 22 12:49:53] DEBUG[17874] res_http_websocket.c: Writing websocket text frame, length 661 [Feb 22 12:49:53] DEBUG[17874] res_http_websocket.c: Writing websocket string of length 643 [Feb 22 12:49:53] DEBUG[17874] res_http_websocket.c: Writing websocket text frame, length 643 [Feb 22 12:49:53] DEBUG[17874] res_http_websocket.c: Writing websocket string of length 665 [Feb 22 12:49:53] DEBUG[17874] res_http_websocket.c: Writing websocket text frame, length 665 [Feb 22 12:49:53] DEBUG[17874] res_http_websocket.c: Writing websocket string of length 592 [Feb 22 12:49:53] DEBUG[17874] res_http_websocket.c: Writing websocket text frame, length 592 [Feb 22 12:49:53] DEBUG[17874] res_http_websocket.c: Writing websocket string of length 664 [Feb 22 12:49:53] DEBUG[17874] res_http_websocket.c: Writing websocket text frame, length 664 [Feb 22 12:49:53] DEBUG[17874] res_http_websocket.c: Writing websocket string of length 656 [Feb 22 12:49:53] DEBUG[17874] res_http_websocket.c: Writing websocket text frame, length 656 [Feb 22 12:49:53] DEBUG[17874] res_http_websocket.c: Writing websocket string of length 632 [Feb 22 12:49:53] DEBUG[17874] res_http_websocket.c: Writing websocket text frame, length 632 [Feb 22 12:49:53] DEBUG[17874] res_http_websocket.c: Writing websocket string of length 599 [Feb 22 12:49:53] DEBUG[17874] res_http_websocket.c: Writing websocket text frame, length 599 [Feb 22 12:49:55] DEBUG[17969] http.c: HTTP opening session. Top level [Feb 22 12:49:55] DEBUG[17969] http.c: HTTP Request URI is /ari/channels/1519332593.0 [Feb 22 12:49:55] DEBUG[17969] http.c: match request [ari/channels/1519332593.0] with handler [httpstatus] len 10 [Feb 22 12:49:55] DEBUG[17969] http.c: match request [ari/channels/1519332593.0] with handler [static] len 6 [Feb 22 12:49:55] DEBUG[17969] http.c: match request [ari/channels/1519332593.0] with handler [ari] len 3 [Feb 22 12:49:55] DEBUG[17969] http.c: Match made with [ari] [Feb 22 12:49:55] DEBUG[17969] http.c: HTTP consuming request body [Feb 22 12:49:55] DEBUG[17969] res_ari.c: Finding handler for channels [Feb 22 12:49:55] DEBUG[17969] res_ari.c: Checking endpoints [Feb 22 12:49:55] DEBUG[17969] res_ari.c: Checking bridges [Feb 22 12:49:55] DEBUG[17969] res_ari.c: Checking sounds [Feb 22 12:49:55] DEBUG[17969] res_ari.c: Checking asterisk [Feb 22 12:49:55] DEBUG[17969] res_ari.c: Checking channels [Feb 22 12:49:55] DEBUG[17969] res_ari.c: Got it! [Feb 22 12:49:55] DEBUG[17969] res_ari.c: Finding handler for 1519332593.0 [Feb 22 12:49:55] DEBUG[17969] res_ari.c: Checking create [Feb 22 12:49:55] DEBUG[17969] res_ari.c: Checking channelId [Feb 22 12:49:55] DEBUG[17969] res_ari.c: Got it! [Feb 22 12:49:55] DEBUG[17969] channel.c: Soft-Hanging (0x20) up channel 'SIP/199.68.168.27-00000000' [Feb 22 12:49:55] DEBUG[17969] http.c: HTTP keeping session open. status_code:204 [Feb 22 12:49:55] DEBUG[17964][C-00000001] stasis/app.c: App 'call-control' not subscribed to channel '1519332593.0' [Feb 22 12:49:55] DEBUG[17964][C-00000001] pbx.c: Extension 17608714288, priority 2 returned normally even though call was hung up [Feb 22 12:49:55] DEBUG[17964][C-00000001] channel.c: Soft-Hanging (0x10) up channel 'SIP/199.68.168.27-00000000' [Feb 22 12:49:55] DEBUG[17874] res_http_websocket.c: Writing websocket string of length 625 [Feb 22 12:49:55] DEBUG[17874] res_http_websocket.c: Writing websocket text frame, length 625 [Feb 22 12:49:55] DEBUG[17964][C-00000001] channel.c: Channel 0x7f7958015658 'SIP/199.68.168.27-00000000' hanging up. Refs: 2 [Feb 22 12:49:55] DEBUG[17964][C-00000001] chan_sip.c: Hangup call SIP/199.68.168.27-00000000, SIP callid 150721772-0-1520124388@199.68.168.21 [Feb 22 12:49:55] DEBUG[17964][C-00000001] chan_sip.c: Hanging up channel in state Ring (not UP) [Feb 22 12:49:55] DEBUG[17964][C-00000001] chan_sip.c: AST hangup cause 16 (no match found in SIP) [Feb 22 12:49:55] DEBUG[17874] res_http_websocket.c: Writing websocket string of length 583 [Feb 22 12:49:55] DEBUG[17874] res_http_websocket.c: Writing websocket text frame, length 583 [Feb 22 12:49:55] DEBUG[17964][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 603' onto UDP socket destined for 199.68.168.27:5060 [Feb 22 12:49:55] DEBUG[17964][C-00000001] channel.c: Channel 0x7f7958015658 'SIP/199.68.168.27-00000000' destroying [Feb 22 12:49:55] DEBUG[17874] res_http_websocket.c: Writing websocket string of length 639 [Feb 22 12:49:55] DEBUG[17874] res_http_websocket.c: Writing websocket text frame, length 639 [Feb 22 12:49:55] DEBUG[17874] res_http_websocket.c: Writing websocket string of length 625 [Feb 22 12:49:55] DEBUG[17874] res_http_websocket.c: Writing websocket text frame, length 625 [Feb 22 12:49:55] DEBUG[17874] res_http_websocket.c: Writing websocket string of length 639 [Feb 22 12:49:55] DEBUG[17874] res_http_websocket.c: Writing websocket text frame, length 639 [Feb 22 12:49:55] DEBUG[17667] cdr.c: Finalized CDR for SIP/199.68.168.27-00000000 - start 1519332593.802948 answer 0.000000 end 1519332595.164126 dispo NO ANSWER [Feb 22 12:49:55] DEBUG[17874] stasis/app.c: App 'call-control' not subscribed to channel '1519332593.0' [Feb 22 12:49:55] DEBUG[17667] cdr.c: Skipping CDR for SIP/199.68.168.27-00000000 since we weren't answered [Feb 22 12:49:55] DEBUG[17663] devicestate.c: No provider found, checking channel drivers for SIP - 199.68.168.27 [Feb 22 12:49:55] DEBUG[17663] chan_sip.c: Checking device state for peer 199.68.168.27 [Feb 22 12:49:55] DEBUG[17663] devicestate.c: Changing state for SIP/199.68.168.27 - state 4 (Invalid) [Feb 22 12:49:55] DEBUG[17675] chan_sip.c: = Looking for Call ID: 150721772-0-1520124388@199.68.168.21 (Checking From) --From tag sansay503340733rdb1068 --To-tag as33c5518e [Feb 22 12:49:55] DEBUG[17675][C-00000001] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Feb 22 12:49:55] DEBUG[17675][C-00000001] chan_sip.c: Stopping retransmission on '150721772-0-1520124388@199.68.168.21' of Response 1: Match Found