[Feb 22 12:36:42] DEBUG[11519] chan_sip.c: = Looking for Call ID: 1c6f8a936ecda596-4595@10.16.40.37 (Checking From) --From tag 9a0e3170bc9986b2a86bdf0478322e37-d40d --To-tag [Feb 22 12:36:42] DEBUG[11519] acl.c: For destination '10.16.40.37', our source address is '199.180.211.19'. [Feb 22 12:36:42] DEBUG[11519] chan_sip.c: Setting AST_TRANSPORT_UDP with address 199.180.211.19:5060 [Feb 22 12:36:42] DEBUG[11519] netsock2.c: Splitting '10.16.40.37' into... [Feb 22 12:36:42] DEBUG[11519] netsock2.c: ...host '10.16.40.37' and port ''. [Feb 22 12:36:42] DEBUG[11519] chan_sip.c: Allocating new SIP dialog for 1c6f8a936ecda596-4595@10.16.40.37 - OPTIONS (No RTP) [Feb 22 12:36:42] DEBUG[11519] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Feb 22 12:36:42] DEBUG[11519] netsock2.c: Splitting '199.180.211.19:5060' into... [Feb 22 12:36:42] DEBUG[11519] netsock2.c: ...host '199.180.211.19' and port ''. [Feb 22 12:36:42] DEBUG[11519] netsock2.c: Splitting 'localhost' into... [Feb 22 12:36:42] DEBUG[11519] netsock2.c: ...host 'localhost' and port ''. [Feb 22 12:36:42] DEBUG[11519] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.16.40.37:5060 [Feb 22 12:36:43] DEBUG[11519] chan_sip.c: = Looking for Call ID: 56be9cd3615a3abd-4683@10.16.40.38 (Checking From) --From tag d3e9c9fb5975f59021bee3c8286f890c-48a6 --To-tag [Feb 22 12:36:43] DEBUG[11519] acl.c: For destination '10.16.40.38', our source address is '199.180.211.19'. [Feb 22 12:36:43] DEBUG[11519] chan_sip.c: Setting AST_TRANSPORT_UDP with address 199.180.211.19:5060 [Feb 22 12:36:43] DEBUG[11519] netsock2.c: Splitting '10.16.40.38' into... [Feb 22 12:36:43] DEBUG[11519] netsock2.c: ...host '10.16.40.38' and port ''. [Feb 22 12:36:43] DEBUG[11519] chan_sip.c: Allocating new SIP dialog for 56be9cd3615a3abd-4683@10.16.40.38 - OPTIONS (No RTP) [Feb 22 12:36:43] DEBUG[11519] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Feb 22 12:36:43] DEBUG[11519] netsock2.c: Splitting '199.180.211.19:5060' into... [Feb 22 12:36:43] DEBUG[11519] netsock2.c: ...host '199.180.211.19' and port ''. [Feb 22 12:36:43] DEBUG[11519] netsock2.c: Splitting 'localhost' into... [Feb 22 12:36:43] DEBUG[11519] netsock2.c: ...host 'localhost' and port ''. [Feb 22 12:36:43] DEBUG[11519] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.16.40.38:5060 [Feb 22 12:36:52] DEBUG[11519] chan_sip.c: = Looking for Call ID: 994359424_128644630@67.231.5.176 (Checking From) --From tag gK0453e9f5 --To-tag [Feb 22 12:36:52] DEBUG[11519] acl.c: For destination '74.123.82.220', our source address is '199.180.211.19'. [Feb 22 12:36:52] DEBUG[11519] chan_sip.c: Setting AST_TRANSPORT_UDP with address 199.180.211.19:5060 [Feb 22 12:36:52] DEBUG[11519] netsock2.c: Splitting '74.123.82.220:5060' into... [Feb 22 12:36:52] DEBUG[11519] netsock2.c: ...host '74.123.82.220' and port '5060'. [Feb 22 12:36:52] DEBUG[11519] chan_sip.c: Allocating new SIP dialog for 994359424_128644630@67.231.5.176 - INVITE (No RTP) [Feb 22 12:36:52] DEBUG[11519][C-00000001] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Feb 22 12:36:52] DEBUG[11519][C-00000001] sip/reqresp_parser.c: Begin: parsing SIP "Supported: timer,100rel,replaces" [Feb 22 12:36:52] DEBUG[11519][C-00000001] sip/reqresp_parser.c: Found SIP option: -timer- [Feb 22 12:36:52] DEBUG[11519][C-00000001] sip/reqresp_parser.c: Matched SIP option: timer [Feb 22 12:36:52] DEBUG[11519][C-00000001] sip/reqresp_parser.c: Found SIP option: -100rel- [Feb 22 12:36:52] DEBUG[11519][C-00000001] sip/reqresp_parser.c: Matched SIP option: 100rel [Feb 22 12:36:52] DEBUG[11519][C-00000001] sip/reqresp_parser.c: Found SIP option: -replaces- [Feb 22 12:36:52] DEBUG[11519][C-00000001] sip/reqresp_parser.c: Matched SIP option: replaces [Feb 22 12:36:52] DEBUG[11519][C-00000001] netsock2.c: Splitting '74.123.82.220:5060' into... [Feb 22 12:36:52] DEBUG[11519][C-00000001] netsock2.c: ...host '74.123.82.220' and port '5060'. [Feb 22 12:36:52] DEBUG[11519][C-00000001] netsock2.c: Splitting '67.231.5.176' into... [Feb 22 12:36:52] DEBUG[11519][C-00000001] netsock2.c: ...host '67.231.5.176' and port ''. [Feb 22 12:36:52] DEBUG[11519][C-00000001] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f381c00b128' [Feb 22 12:36:52] DEBUG[11519][C-00000001] res_rtp_asterisk.c: Allocated port 18598 for RTP instance '0x7f381c00b128' [Feb 22 12:36:52] DEBUG[11519][C-00000001] res_rtp_asterisk.c: Creating ICE session 0.0.0.0:18598 (18598) for RTP instance '0x7f381c00b128' [Feb 22 12:36:52] DEBUG[11519][C-00000001] netsock2.c: Splitting '199.180.211.19' into... [Feb 22 12:36:52] DEBUG[11519][C-00000001] netsock2.c: ...host '199.180.211.19' and port ''. [Feb 22 12:36:52] DEBUG[11519][C-00000001] netsock2.c: Splitting '199.180.211.19' into... [Feb 22 12:36:52] DEBUG[11519][C-00000001] netsock2.c: ...host '199.180.211.19' and port ''. [Feb 22 12:36:52] DEBUG[11519][C-00000001] netsock2.c: Splitting '172.17.0.1' into... [Feb 22 12:36:52] DEBUG[11519][C-00000001] netsock2.c: ...host '172.17.0.1' and port ''. [Feb 22 12:36:52] DEBUG[11519][C-00000001] netsock2.c: Splitting '172.17.0.1' into... [Feb 22 12:36:52] DEBUG[11519][C-00000001] netsock2.c: ...host '172.17.0.1' and port ''. [Feb 22 12:36:52] DEBUG[11519][C-00000001] rtp_engine.c: RTP instance '0x7f381c00b128' is setup and ready to go [Feb 22 12:36:52] DEBUG[11519][C-00000001] netsock2.c: Splitting 'pod09-asterisk02.dev-core.fvscloud.com' into... [Feb 22 12:36:52] DEBUG[11519][C-00000001] netsock2.c: ...host 'pod09-asterisk02.dev-core.fvscloud.com' and port ''. [Feb 22 12:36:52] DEBUG[11519][C-00000001] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f381c00b128' [Feb 22 12:36:52] VERBOSE[11519][C-00000001] netsock2.c: Using SIP RTP CoS mark 5 [Feb 22 12:36:52] DEBUG[11519][C-00000001] chan_sip.c: Setting NAT on RTP to On [Feb 22 12:36:52] DEBUG[11519][C-00000001] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Feb 22 12:36:52] DEBUG[11519][C-00000001] chan_sip.c: Processing session-level SDP o=Sansay-VSXi 188 1 IN IP4 74.123.82.220... OK. [Feb 22 12:36:52] DEBUG[11519][C-00000001] chan_sip.c: Processing session-level SDP s=Session Controller... UNSUPPORTED OR FAILED. [Feb 22 12:36:52] DEBUG[11519][C-00000001] netsock2.c: Splitting '67.231.5.91' into... [Feb 22 12:36:52] DEBUG[11519][C-00000001] netsock2.c: ...host '67.231.5.91' and port ''. [Feb 22 12:36:52] DEBUG[11519][C-00000001] chan_sip.c: Processing session-level SDP c=IN IP4 67.231.5.91... OK. [Feb 22 12:36:52] DEBUG[11519][C-00000001] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Feb 22 12:36:52] DEBUG[11519][C-00000001] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7f37f3c50a00 [Feb 22 12:36:52] DEBUG[11519][C-00000001] rtp_engine.c: Setting tx payload type 18 based on m type on 0x7f37f3c50a00 [Feb 22 12:36:52] DEBUG[11519][C-00000001] rtp_engine.c: Setting tx payload type 101 based on m type on 0x7f37f3c50a00 [Feb 22 12:36:52] DEBUG[11519][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Feb 22 12:36:52] DEBUG[11519][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK. [Feb 22 12:36:52] DEBUG[11519][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=fmtp:18 annexb=no... OK. [Feb 22 12:36:52] DEBUG[11519][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Feb 22 12:36:52] DEBUG[11519][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED OR FAILED. [Feb 22 12:36:52] DEBUG[11519][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Feb 22 12:36:52] DEBUG[11519][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK. [Feb 22 12:36:52] DEBUG[11519][C-00000001] rtp_engine.c: Crossover copying tx to rx payload mapping 0 (0x7f381c009c70) from 0x7f37f3c50a00 to 0x7f37f3c50a00 [Feb 22 12:36:52] DEBUG[11519][C-00000001] rtp_engine.c: Crossover copying tx to rx payload mapping 18 (0x7f381c00adc0) from 0x7f37f3c50a00 to 0x7f37f3c50a00 [Feb 22 12:36:52] DEBUG[11519][C-00000001] rtp_engine.c: Crossover copying tx to rx payload mapping 101 (0x1eef420) from 0x7f37f3c50a00 to 0x7f37f3c50a00 [Feb 22 12:36:52] DEBUG[11519][C-00000001] acl.c: For destination '67.231.5.91', our source address is '199.180.211.19'. [Feb 22 12:36:52] DEBUG[11519][C-00000001] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f381c00b128' [Feb 22 12:36:52] VERBOSE[11519][C-00000001] res_rtp_asterisk.c: 0x7f381c00c110 -- Strict RTP learning after remote address set to: 67.231.5.91:46366 [Feb 22 12:36:52] DEBUG[11519][C-00000001] rtp_engine.c: Copying rx payload mapping 0 (0x7f381c009c70) from 0x7f37f3c50a00 to 0x7f381c00b2f0 [Feb 22 12:36:52] DEBUG[11519][C-00000001] rtp_engine.c: Copying rx payload mapping 18 (0x7f381c00adc0) from 0x7f37f3c50a00 to 0x7f381c00b2f0 [Feb 22 12:36:52] DEBUG[11519][C-00000001] rtp_engine.c: Copying rx payload mapping 101 (0x1eef420) from 0x7f37f3c50a00 to 0x7f381c00b2f0 [Feb 22 12:36:52] DEBUG[11519][C-00000001] rtp_engine.c: Copying tx payload mapping 0 (0x7f381c009c70) from 0x7f37f3c50a00 to 0x7f381c00b2f0 [Feb 22 12:36:52] DEBUG[11519][C-00000001] rtp_engine.c: Copying tx payload mapping 18 (0x7f381c00adc0) from 0x7f37f3c50a00 to 0x7f381c00b2f0 [Feb 22 12:36:52] DEBUG[11519][C-00000001] rtp_engine.c: Copying tx payload mapping 101 (0x1eef420) from 0x7f37f3c50a00 to 0x7f381c00b2f0 [Feb 22 12:36:52] DEBUG[11519][C-00000001] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7f381c00b128' [Feb 22 12:36:52] DEBUG[11519][C-00000001] chan_sip.c: We're settling with these formats: (ulaw) [Feb 22 12:36:52] DEBUG[11519][C-00000001] chan_sip.c: Checking SIP call limits for device [Feb 22 12:36:52] DEBUG[11519][C-00000001] chan_sip.c: Updating call counter for incoming call [Feb 22 12:36:52] DEBUG[11519][C-00000001] netsock2.c: Splitting '199.180.211.19:5060' into... [Feb 22 12:36:52] DEBUG[11519][C-00000001] netsock2.c: ...host '199.180.211.19' and port ''. [Feb 22 12:36:52] DEBUG[11519][C-00000001] netsock2.c: Splitting '67.231.5.176' into... [Feb 22 12:36:52] DEBUG[11519][C-00000001] netsock2.c: ...host '67.231.5.176' and port ''. [Feb 22 12:36:52] DEBUG[11519][C-00000001] chan_sip.c: Incoming INVITE with 'timer' option supported [Feb 22 12:36:52] DEBUG[11519][C-00000001] chan_sip.c: INVITE also has "Session-Expires" header. [Feb 22 12:36:52] DEBUG[11519][C-00000001] chan_sip.c: Session-Expires: 1800 [Feb 22 12:36:52] DEBUG[11519][C-00000001] chan_sip.c: Refresher: UAC [Feb 22 12:36:52] DEBUG[11519][C-00000001] chan_sip.c: INVITE also has "Min-SE" header. [Feb 22 12:36:52] DEBUG[11519][C-00000001] chan_sip.c: Received Min-SE: 90 [Feb 22 12:36:52] DEBUG[11519][C-00000001] channel.c: Channel 0x7f381c01a4d8 'SIP/67.231.5.176-00000000' allocated [Feb 22 12:36:52] DEBUG[11519][C-00000001] chan_sip.c: *** Our native formats are (ulaw) [Feb 22 12:36:52] DEBUG[11519][C-00000001] chan_sip.c: *** Joint capabilities are (ulaw) [Feb 22 12:36:52] DEBUG[11519][C-00000001] chan_sip.c: *** Our capabilities are (ulaw) [Feb 22 12:36:52] DEBUG[11519][C-00000001] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw [Feb 22 12:36:52] DEBUG[11519][C-00000001] chan_sip.c: This channel will not be able to handle video. [Feb 22 12:36:52] DEBUG[11519][C-00000001] sip/route.c: sip_route_process_header: [Feb 22 12:36:52] DEBUG[11519][C-00000001] chan_sip.c: SIP/67.231.5.176-00000000: New call is still down.... Trying... [Feb 22 12:36:52] DEBUG[11519][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 74.123.82.220:5060 [Feb 22 12:36:52] DEBUG[13251] res_http_websocket.c: Writing websocket string of length 587 [Feb 22 12:36:52] DEBUG[13251] res_http_websocket.c: Writing websocket text frame, length 587 [Feb 22 12:36:52] DEBUG[11488] devicestate.c: No provider found, checking channel drivers for SIP - 67.231.5.176 [Feb 22 12:36:52] DEBUG[11488] chan_sip.c: Checking device state for peer 67.231.5.176 [Feb 22 12:36:52] DEBUG[11488] devicestate.c: Changing state for SIP/67.231.5.176 - state 4 (Invalid) [Feb 22 12:36:52] DEBUG[13519][C-00000001] pbx_variables.c: Result of 'AbsoluteTimeout' is '14460' [Feb 22 12:36:52] DEBUG[13519][C-00000001] pbx.c: Launching 'Set' [Feb 22 12:36:52] VERBOSE[13519][C-00000001] pbx.c: Executing [17608714288@pstn:1] Set("SIP/67.231.5.176-00000000", "TIMEOUT(absolute)=14460") in new stack [Feb 22 12:36:52] VERBOSE[13519][C-00000001] func_timeout.c: Channel will hangup at 2018-02-22 16:37:52.374 PST. [Feb 22 12:36:52] DEBUG[13519][C-00000001] pbx.c: Launching 'Stasis' [Feb 22 12:36:52] VERBOSE[13519][C-00000001] pbx.c: Executing [17608714288@pstn:2] Stasis("SIP/67.231.5.176-00000000", "call-control") in new stack [Feb 22 12:37:01] DEBUG[11519] chan_sip.c: = Looking for Call ID: 698a87dd59a069f9-3908@10.16.41.19 (Checking From) --From tag 07abbd969da69d175fb87f916a0689d3-c276 --To-tag [Feb 22 12:37:01] DEBUG[11519] acl.c: For destination '10.16.41.19', our source address is '199.180.211.19'. [Feb 22 12:37:01] DEBUG[11519] chan_sip.c: Setting AST_TRANSPORT_UDP with address 199.180.211.19:5060 [Feb 22 12:37:01] DEBUG[11519] netsock2.c: Splitting '10.16.41.19' into... [Feb 22 12:37:01] DEBUG[11519] netsock2.c: ...host '10.16.41.19' and port ''. [Feb 22 12:37:01] DEBUG[11519] chan_sip.c: Allocating new SIP dialog for 698a87dd59a069f9-3908@10.16.41.19 - OPTIONS (No RTP) [Feb 22 12:37:01] DEBUG[11519] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS [Feb 22 12:37:01] DEBUG[11519] netsock2.c: Splitting '199.180.211.19:5060' into... [Feb 22 12:37:01] DEBUG[11519] netsock2.c: ...host '199.180.211.19' and port ''. [Feb 22 12:37:01] DEBUG[11519] netsock2.c: Splitting 'localhost' into... [Feb 22 12:37:01] DEBUG[11519] netsock2.c: ...host 'localhost' and port ''. [Feb 22 12:37:01] DEBUG[11519] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.16.41.19:5060 [Feb 22 12:37:14] DEBUG[11519] chan_sip.c: Auto destroying SIP dialog '1c6f8a936ecda596-4595@10.16.40.37' [Feb 22 12:37:14] DEBUG[11519] chan_sip.c: Destroying SIP dialog 1c6f8a936ecda596-4595@10.16.40.37 [Feb 22 12:37:14] DEBUG[11519] chan_sip.c: ---------- SIP HISTORY for '1c6f8a936ecda596-4595@10.16.40.37' [Feb 22 12:37:14] DEBUG[11519] chan_sip.c: * SIP Call [Feb 22 12:37:14] DEBUG[11519] chan_sip.c: 001. Rx OPTIONS / 10 OPTIONS / sip:199.180.211.19:5060 [Feb 22 12:37:14] DEBUG[11519] chan_sip.c: 002. TxResp SIP/2.0 / 10 OPTIONS - 200 OK [Feb 22 12:37:14] DEBUG[11519] chan_sip.c: 003. SchedDestroy 32000 ms [Feb 22 12:37:14] DEBUG[11519] chan_sip.c: 004. AutoDestroy 1c6f8a936ecda596-4595@10.16.40.37 [Feb 22 12:37:14] DEBUG[11519] chan_sip.c: ---------- END SIP HISTORY for '1c6f8a936ecda596-4595@10.16.40.37' [Feb 22 12:37:15] DEBUG[11519] chan_sip.c: Auto destroying SIP dialog '56be9cd3615a3abd-4683@10.16.40.38' [Feb 22 12:37:15] DEBUG[11519] chan_sip.c: Destroying SIP dialog 56be9cd3615a3abd-4683@10.16.40.38 [Feb 22 12:37:15] DEBUG[11519] chan_sip.c: ---------- SIP HISTORY for '56be9cd3615a3abd-4683@10.16.40.38' [Feb 22 12:37:15] DEBUG[11519] chan_sip.c: * SIP Call [Feb 22 12:37:15] DEBUG[11519] chan_sip.c: 001. Rx OPTIONS / 10 OPTIONS / sip:199.180.211.19:5060 [Feb 22 12:37:15] DEBUG[11519] chan_sip.c: 002. TxResp SIP/2.0 / 10 OPTIONS - 200 OK [Feb 22 12:37:15] DEBUG[11519] chan_sip.c: 003. SchedDestroy 32000 ms [Feb 22 12:37:15] DEBUG[11519] chan_sip.c: 004. AutoDestroy 56be9cd3615a3abd-4683@10.16.40.38 [Feb 22 12:37:15] DEBUG[11519] chan_sip.c: ---------- END SIP HISTORY for '56be9cd3615a3abd-4683@10.16.40.38' [Feb 22 12:37:17] DEBUG[11519] chan_sip.c: = Looking for Call ID: 994359424_128644630@67.231.5.176 (Checking From) --From tag gK0453e9f5 --To-tag [Feb 22 12:37:17] DEBUG[11519][C-00000001] chan_sip.c: **** Received CANCEL (14) - Command in SIP CANCEL [Feb 22 12:37:17] DEBUG[11519][C-00000001] netsock2.c: Splitting '74.123.82.220:5060' into... [Feb 22 12:37:17] DEBUG[11519][C-00000001] netsock2.c: ...host '74.123.82.220' and port '5060'. [Feb 22 12:37:17] DEBUG[11519][C-00000001] chan_sip.c: Setting SIP_ALREADYGONE on dialog 994359424_128644630@67.231.5.176 [Feb 22 12:37:17] DEBUG[11519][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 487' onto UDP socket destined for 74.123.82.220:5060 [Feb 22 12:37:17] DEBUG[11519][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 74.123.82.220:5060 [Feb 22 12:37:17] DEBUG[13519][C-00000001] res_stasis.c: 1519331812.0: Hangup (no more frames) [Feb 22 12:37:17] DEBUG[13519][C-00000001] stasis/app.c: App 'call-control' not subscribed to channel '1519331812.0' [Feb 22 12:37:17] DEBUG[13519][C-00000001] pbx.c: Extension 17608714288, priority 2 returned normally even though call was hung up [Feb 22 12:37:17] DEBUG[13519][C-00000001] channel.c: Soft-Hanging (0x10) up channel 'SIP/67.231.5.176-00000000' [Feb 22 12:37:17] DEBUG[13519][C-00000001] channel.c: Channel 0x7f381c01a4d8 'SIP/67.231.5.176-00000000' hanging up. Refs: 2 [Feb 22 12:37:17] DEBUG[13519][C-00000001] chan_sip.c: Hangup call SIP/67.231.5.176-00000000, SIP callid 994359424_128644630@67.231.5.176 [Feb 22 12:37:17] DEBUG[13519][C-00000001] channel.c: Channel 0x7f381c01a4d8 'SIP/67.231.5.176-00000000' destroying [Feb 22 12:37:17] DEBUG[11492] cdr.c: Finalized CDR for SIP/67.231.5.176-00000000 - start 1519331812.374009 answer 0.000000 end 1519331837.074551 dispo FAILED [Feb 22 12:37:17] DEBUG[11492] cdr.c: Skipping CDR for SIP/67.231.5.176-00000000 since we weren't answered [