SIP over WSS responding with 5060; transport=udp in Contact:
I am using SIP over WebSockets on port 443, most things work correctly, but when I terminate a call that is ringing I can't because port and transport are wrong. Incoming WSS port 443: recv 461 bytes from wss/[50.246.121.173]:34738 at 17:03:00.035305: ------------------------------------------------------------------------ SIP/2.0 180 Ringing Via: SIP/2.0/WSS 18.211.78.106:443;rport;branch=z9hG4bKvNgc7Dy2r4rHS From: "Beth User" <sip:beth@18.211.78.106>;tag=B1564gFygm3jN To: <sip:r6ucrocm@3val7ifjblg6.invalid;transport=ws;received= 50.246.121.173:34738>;tag=aa53u3jvjt CSeq: 10377697 INVITE Call-ID: ff8ac04a-5e46-1238-2787-0251a831415e Supported: outbound User-Agent: nathan@stage.illumy1.com Contact: <sip:r6ucrocm@3val7ifjblg6.invalid;transport=ws> Content-Length: 0 Outgoing WSS port 443: send 760 bytes to wss/[50.246.121.173]:34010 at 17:03:00.061145: ------------------------------------------------------------------------ SIP/2.0 180 Ringing Via: SIP/2.0/WSS vg5qpm92h7dm.invalid;branch=z9hG4bK2823219;received=50.246.121.173;rport=34010 From: "beth@stage.illumy1.com" <sip:beth@stage.illumy1.com>;tag=ukhk0sdsd9 To: <sip:nathan@stage.illumy1.com>;tag=9eKN1tDQp2pDe Call-ID: reo4ds005e1qlr4784v8 CSeq: 2 INVITE Contact: <sip:nathan@18.211.78.106:5060;transport=udp> User-Agent: FreeSWITCH-mod_sofia/1.10.0-release~64bit Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: path, replaces Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Content-Length: 0 As you can see, Contact incorrectly states port and transport.
<> nathan stratton
Somewhat related, I had similar problem with SIP over TLS transport. Outgoing FS INVITE not putting its actual ephemeral port in the Contact, putting some default instead. I couldn't find anything in configuration to alter that. Maybe your experience will be better / different.
On Sep 30, 2019, at 13:13, Nathan Stratton <nathan@robotics.net> wrote:
I am using SIP over WebSockets on port 443, most things work correctly, but when I terminate a call that is ringing I can't because port and transport are wrong.
Incoming WSS port 443:
recv 461 bytes from wss/[50.246.121.173]:34738 at 17:03:00.035305: ------------------------------------------------------------------------ SIP/2.0 180 Ringing Via: SIP/2.0/WSS 18.211.78.106:443;rport;branch=z9hG4bKvNgc7Dy2r4rHS From: "Beth User" <sip:beth@18.211.78.106>;tag=B1564gFygm3jN To: <sip:r6ucrocm@3val7ifjblg6.invalid;transport=ws;received=50.246.121.173:34738>;tag=aa53u3jvjt CSeq: 10377697 INVITE Call-ID: ff8ac04a-5e46-1238-2787-0251a831415e Supported: outbound User-Agent: nathan@stage.illumy1.com Contact: <sip:r6ucrocm@3val7ifjblg6.invalid;transport=ws> Content-Length: 0
Outgoing WSS port 443:
send 760 bytes to wss/[50.246.121.173]:34010 at 17:03:00.061145: ------------------------------------------------------------------------ SIP/2.0 180 Ringing Via: SIP/2.0/WSS vg5qpm92h7dm.invalid;branch=z9hG4bK2823219;received=50.246.121.173;rport=34010 From: "beth@stage.illumy1.com" <sip:beth@stage.illumy1.com>;tag=ukhk0sdsd9 To: <sip:nathan@stage.illumy1.com>;tag=9eKN1tDQp2pDe Call-ID: reo4ds005e1qlr4784v8 CSeq: 2 INVITE Contact: <sip:nathan@18.211.78.106:5060;transport=udp> User-Agent: FreeSWITCH-mod_sofia/1.10.0-release~64bit Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: path, replaces Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Content-Length: 0
As you can see, Contact incorrectly states port and transport.
<> nathan stratton
The FreeSWITCH project is sponsored by SignalWire https://signalwire.com Enhance your FreeSWITCH install with disruptive priced SMS and PSTN services. Build your next product on our scalable cloud platform.
Join our online community to chat in real time https://signalwire.community
Professional FreeSWITCH Services sales@freeswitch.com https://freeswitch.com
Official FreeSWITCH Sites https://freeswitch.com/oss https://freeswitch.org/confluence https://cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users https://freeswitch.com
Hi Nathan, If you could provide the full SIP trace for a sample, that would be great. While the Contact header is indeed typically pointing back at the standard SIP IP/port combination (i.e. non-WebSocket), most JS SIP client library gracefully work around it (even without rport hints). Do you use a public stack for the client portion or a implementation? -Ciprian On Mon, 30 Sep 2019 at 13:46, Nathan Stratton <nathan@robotics.net> wrote:
I am using SIP over WebSockets on port 443, most things work correctly, but when I terminate a call that is ringing I can't because port and transport are wrong.
Incoming WSS port 443:
recv 461 bytes from wss/[50.246.121.173]:34738 at 17:03:00.035305: ------------------------------------------------------------------------ SIP/2.0 180 Ringing Via: SIP/2.0/WSS 18.211.78.106:443;rport;branch=z9hG4bKvNgc7Dy2r4rHS From: "Beth User" <sip:beth@18.211.78.106>;tag=B1564gFygm3jN To: <sip:r6ucrocm@3val7ifjblg6.invalid;transport=ws;received= 50.246.121.173:34738>;tag=aa53u3jvjt CSeq: 10377697 INVITE Call-ID: ff8ac04a-5e46-1238-2787-0251a831415e Supported: outbound User-Agent: nathan@stage.illumy1.com Contact: <sip:r6ucrocm@3val7ifjblg6.invalid;transport=ws> Content-Length: 0
Outgoing WSS port 443:
send 760 bytes to wss/[50.246.121.173]:34010 at 17:03:00.061145: ------------------------------------------------------------------------ SIP/2.0 180 Ringing Via: SIP/2.0/WSS vg5qpm92h7dm.invalid;branch=z9hG4bK2823219;received=50.246.121.173;rport=34010 From: "beth@stage.illumy1.com" <sip:beth@stage.illumy1.com>;tag=ukhk0sdsd9 To: <sip:nathan@stage.illumy1.com>;tag=9eKN1tDQp2pDe Call-ID: reo4ds005e1qlr4784v8 CSeq: 2 INVITE Contact: <sip:nathan@18.211.78.106:5060;transport=udp> User-Agent: FreeSWITCH-mod_sofia/1.10.0-release~64bit Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: path, replaces Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Content-Length: 0
As you can see, Contact incorrectly states port and transport.
<> nathan stratton
The FreeSWITCH project is sponsored by SignalWire https://signalwire.com Enhance your FreeSWITCH install with disruptive priced SMS and PSTN services. Build your next product on our scalable cloud platform.
Join our online community to chat in real time https://signalwire.community
Professional FreeSWITCH Services sales@freeswitch.com https://freeswitch.com
Official FreeSWITCH Sites https://freeswitch.com/oss https://freeswitch.org/confluence https://cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users https://freeswitch.com
-- Best Regards, Ciprian Dosoftei The information transmitted is intended only for the addressee and may contain privileged and/or confidential material. If you are not the intended recipient, kindly contact the sender and delete the message. Any disclosure, distribution or copying of this message is strictly prohibited without the expressed permission of the sender.
On Mon, Sep 30, 2019 at 4:10 PM Ciprian Dosoftei <ciprian.dosoftei@gmail.com> wrote:
Hi Nathan,
If you could provide the full SIP trace for a sample, that would be great.
Sure, see below. While the Contact header is indeed typically pointing back at the standard
SIP IP/port combination (i.e. non-WebSocket), most JS SIP client library gracefully work around it (even without rport hints).
So this is a know issue?
Do you use a public stack for the client portion or a implementation?
We are using SIP.js on the web side and Libre SIP stack for iOS and Android, both have issues with this bug. +OK log level [7] freeswitch@as1-east> sofia global siptrace on +OK Global siptrace on recv 2642 bytes from wss/[50.246.121.173]:34010 at 20:27:36.440748: ------------------------------------------------------------------------ INVITE sip:nathan@stage.illumy1.com SIP/2.0 Via: SIP/2.0/WSS vg5qpm92h7dm.invalid;branch=z9hG4bK6235908 To: <sip:nathan@stage.illumy1.com> From: "beth@stage.illumy1.com" <sip:beth@stage.illumy1.com>;tag=36ov91agi3 CSeq: 1 INVITE Call-ID: reo4dv21qm4aauclal7r Max-Forwards: 70 X-Foo: true Contact: <sip:0s9riicj@vg5qpm92h7dm.invalid;transport=ws;ob> Allow: ACK,CANCEL,INVITE,MESSAGE,BYE,OPTIONS,INFO,NOTIFY,REFER Supported: outbound User-Agent: beth@stage.illumy1.com Content-Type: application/sdp Content-Length: 2108 v=0 o=- 3923831751587036465 2 IN IP4 127.0.0.1 s=- t=0 0 a=group:BUNDLE 0 a=msid-semantic: WMS DrxEOjCVvHNi3DtuKJs175ibnTtb2huY2WVc m=audio 61006 UDP/TLS/RTP/SAVPF 111 103 104 9 0 8 106 105 13 110 112 113 126 c=IN IP4 18.204.23.155 a=rtcp:9 IN IP4 0.0.0.0 a=candidate:1978755251 1 udp 2122260223 10.88.65.80 34027 typ host generation 0 network-id 1 network-cost 10 a=candidate:3702450022 1 udp 1686052607 50.246.121.173 34027 typ srflx raddr 10.88.65.80 rport 34027 generation 0 network-id 1 network-cost 10 a=candidate:3425785639 1 udp 41885439 18.204.23.155 61006 typ relay raddr 50.246.121.173 rport 34027 generation 0 network-id 1 network-cost 10 a=candidate:997364803 1 tcp 1518280447 10.88.65.80 9 typ host tcptype active generation 0 network-id 1 network-cost 10 a=ice-ufrag:EVJX a=ice-pwd:ppoOZcwEGehOPKMM03ol7g5r a=ice-options:trickle a=fingerprint:sha-256 37:F4:29:14:94:6A:87:51:7E:44:81:FA:71:BF:22:D7:71:0C:02:93:49:61:36:3A:A6:AA:B5:34:2B:CA:1F:55 a=setup:actpass a=mid:0 a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level a=extmap:2 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01 a=extmap:3 urn:ietf:params:rtp-hdrext:sdes:mid a=extmap:4 urn:ietf:params:rtp-hdrext:sdes:rtp-stream-id a=extmap:5 urn:ietf:params:rtp-hdrext:sdes:repaired-rtp-stream-id a=sendrecv a=msid:DrxEOjCVvHNi3DtuKJs175ibnTtb2huY2WVc 4fdf8bec-c8e1-42d1-a872-db6864ef5ac2 a=rtcp-mux a=rtpmap:111 opus/48000/2 a=rtcp-fb:111 transport-cc a=fmtp:111 minptime=10;useinbandfec=1 a=rtpmap:103 ISAC/16000 a=rtpmap:104 ISAC/32000 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:106 CN/32000 a=rtpmap:105 CN/16000 a=rtpmap:13 CN/8000 a=rtpmap:110 telephone-event/48000 a=rtpmap:112 telephone-event/32000 a=rtpmap:113 telephone-event/16000 a=rtpmap:126 telephone-event/8000 a=ssrc:767982924 cname:D8OaexP97luPw4OL a=ssrc:767982924 msid:DrxEOjCVvHNi3DtuKJs175ibnTtb2huY2WVc 4fdf8bec-c8e1-42d1-a872-db6864ef5ac2 a=ssrc:767982924 mslabel:DrxEOjCVvHNi3DtuKJs175ibnTtb2huY2WVc a=ssrc:767982924 label:4fdf8bec-c8e1-42d1-a872-db6864ef5ac2 2019-09-30 20:27:36.431835 [NOTICE] switch_channel.c:1118 New Channel sofia/internal/beth@stage.illumy1.com [59f602c8-5c38-4c8b-984f-7f09197e9fa3] 2019-09-30 20:27:36.431835 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/beth@stage.illumy1.com) Running State Change CS_NEW (Cur 3 Tot 925) 2019-09-30 20:27:36.431835 [DEBUG] sofia.c:10242 sofia/internal/ beth@stage.illumy1.com receiving invite from 50.246.121.173:34010 version: 1.10.0 -release 64bit 2019-09-30 20:27:36.431835 [DEBUG] sofia.c:10336 verifying acl "internal" for ip/port 50.246.121.173:0. 2019-09-30 20:27:36.431835 [DEBUG] switch_core_state_machine.c:604 (sofia/internal/beth@stage.illumy1.com) State NEW send 853 bytes to wss/[50.246.121.173]:34010 at 20:27:36.445754: ------------------------------------------------------------------------ SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/WSS vg5qpm92h7dm.invalid;branch=z9hG4bK6235908;received=50.246.121.173;rport=34010 From: "beth@stage.illumy1.com" <sip:beth@stage.illumy1.com>;tag=36ov91agi3 To: <sip:nathan@stage.illumy1.com>;tag=Up8tp3554QHpj Call-ID: reo4dv21qm4aauclal7r CSeq: 1 INVITE User-Agent: FreeSWITCH-mod_sofia/1.10.0-release~64bit Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: path, replaces Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Proxy-Authenticate: Digest realm="stage.illumy1.com", nonce="921a7927-e0ba-4eb3-8532-cb4c1490721c", algorithm=MD5, qop="auth" Content-Length: 0 2019-09-30 20:27:36.431835 [DEBUG] sofia.c:2426 detaching session 59f602c8-5c38-4c8b-984f-7f09197e9fa3 recv 316 bytes from wss/[50.246.121.173]:34010 at 20:27:36.505757: ------------------------------------------------------------------------ ACK sip:nathan@stage.illumy1.com SIP/2.0 Via: SIP/2.0/WSS vg5qpm92h7dm.invalid;branch=z9hG4bK6235908 To: <sip:nathan@stage.illumy1.com>;tag=Up8tp3554QHpj From: "beth@stage.illumy1.com" <sip:beth@stage.illumy1.com>;tag=36ov91agi3 Call-ID: reo4dv21qm4aauclal7r CSeq: 1 ACK Max-Forwards: 70 Content-Length: 0 recv 2902 bytes from wss/[50.246.121.173]:34010 at 20:27:36.505833: ------------------------------------------------------------------------ INVITE sip:nathan@stage.illumy1.com SIP/2.0 Via: SIP/2.0/WSS vg5qpm92h7dm.invalid;branch=z9hG4bK9166577 To: <sip:nathan@stage.illumy1.com> From: "beth@stage.illumy1.com" <sip:beth@stage.illumy1.com>;tag=36ov91agi3 CSeq: 2 INVITE Call-ID: reo4dv21qm4aauclal7r Max-Forwards: 70 Proxy-Authorization: Digest algorithm=MD5, username="beth", realm=" stage.illumy1.com", nonce="921a7927-e0ba-4eb3-8532-cb4c1490721c", uri=" sip:nathan@stage.illumy1.com", response="68b33afa613ebdf80f0694bc454dac65", qop=auth, cnonce="k3s2qg42vh0i", nc=00000001 X-Foo: true Contact: <sip:0s9riicj@vg5qpm92h7dm.invalid;transport=ws;ob> Allow: ACK,CANCEL,INVITE,MESSAGE,BYE,OPTIONS,INFO,NOTIFY,REFER Supported: outbound User-Agent: beth@stage.illumy1.com Content-Type: application/sdp Content-Length: 2108 v=0 o=- 3923831751587036465 2 IN IP4 127.0.0.1 s=- t=0 0 a=group:BUNDLE 0 a=msid-semantic: WMS DrxEOjCVvHNi3DtuKJs175ibnTtb2huY2WVc m=audio 61006 UDP/TLS/RTP/SAVPF 111 103 104 9 0 8 106 105 13 110 112 113 126 c=IN IP4 18.204.23.155 a=rtcp:9 IN IP4 0.0.0.0 a=candidate:1978755251 1 udp 2122260223 10.88.65.80 34027 typ host generation 0 network-id 1 network-cost 10 a=candidate:3702450022 1 udp 1686052607 50.246.121.173 34027 typ srflx raddr 10.88.65.80 rport 34027 generation 0 network-id 1 network-cost 10 a=candidate:3425785639 1 udp 41885439 18.204.23.155 61006 typ relay raddr 50.246.121.173 rport 34027 generation 0 network-id 1 network-cost 10 a=candidate:997364803 1 tcp 1518280447 10.88.65.80 9 typ host tcptype active generation 0 network-id 1 network-cost 10 a=ice-ufrag:EVJX a=ice-pwd:ppoOZcwEGehOPKMM03ol7g5r a=ice-options:trickle a=fingerprint:sha-256 37:F4:29:14:94:6A:87:51:7E:44:81:FA:71:BF:22:D7:71:0C:02:93:49:61:36:3A:A6:AA:B5:34:2B:CA:1F:55 a=setup:actpass a=mid:0 a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level a=extmap:2 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01 a=extmap:3 urn:ietf:params:rtp-hdrext:sdes:mid a=extmap:4 urn:ietf:params:rtp-hdrext:sdes:rtp-stream-id a=extmap:5 urn:ietf:params:rtp-hdrext:sdes:repaired-rtp-stream-id a=sendrecv a=msid:DrxEOjCVvHNi3DtuKJs175ibnTtb2huY2WVc 4fdf8bec-c8e1-42d1-a872-db6864ef5ac2 a=rtcp-mux a=rtpmap:111 opus/48000/2 a=rtcp-fb:111 transport-cc a=fmtp:111 minptime=10;useinbandfec=1 a=rtpmap:103 ISAC/16000 a=rtpmap:104 ISAC/32000 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:106 CN/32000 a=rtpmap:105 CN/16000 a=rtpmap:13 CN/8000 a=rtpmap:110 telephone-event/48000 a=rtpmap:112 telephone-event/32000 a=rtpmap:113 telephone-event/16000 a=rtpmap:126 telephone-event/8000 a=ssrc:767982924 cname:D8OaexP97luPw4OL a=ssrc:767982924 msid:DrxEOjCVvHNi3DtuKJs175ibnTtb2huY2WVc 4fdf8bec-c8e1-42d1-a872-db6864ef5ac2 a=ssrc:767982924 mslabel:DrxEOjCVvHNi3DtuKJs175ibnTtb2huY2WVc a=ssrc:767982924 label:4fdf8bec-c8e1-42d1-a872-db6864ef5ac2 2019-09-30 20:27:36.491837 [DEBUG] sofia.c:2535 Re-attaching to session 59f602c8-5c38-4c8b-984f-7f09197e9fa3 2019-09-30 20:27:36.511840 [DEBUG] sofia.c:10242 sofia/internal/ beth@stage.illumy1.com receiving invite from 50.246.121.173:34010 version: 1.10.0 -release 64bit 2019-09-30 20:27:36.511840 [DEBUG] sofia.c:10336 verifying acl "internal" for ip/port 50.246.121.173:0. 2019-09-30 20:27:36.531844 [DEBUG] sofia.c:11432 Setting NAT mode based on via received 2019-09-30 20:27:36.531844 [DEBUG] sofia.c:7289 Channel sofia/internal/ beth@stage.illumy1.com entering state [received][100] 2019-09-30 20:27:36.531844 [DEBUG] sofia.c:7299 Remote SDP: v=0 o=- 3923831751587036465 2 IN IP4 127.0.0.1 s=- t=0 0 a=group:BUNDLE 0 a=msid-semantic: WMS DrxEOjCVvHNi3DtuKJs175ibnTtb2huY2WVc m=audio 61006 UDP/TLS/RTP/SAVPF 111 103 104 9 0 8 106 105 13 110 112 113 126 c=IN IP4 18.204.23.155 a=rtpmap:111 opus/48000/2 a=fmtp:111 minptime=10;useinbandfec=1 a=rtpmap:103 ISAC/16000 a=rtpmap:104 ISAC/32000 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:106 CN/32000 a=rtpmap:105 CN/16000 a=rtpmap:13 CN/8000 a=rtpmap:110 telephone-event/48000 a=rtpmap:112 telephone-event/32000 a=rtpmap:113 telephone-event/16000 a=rtpmap:126 telephone-event/8000 a=rtcp:9 IN IP4 0.0.0.0 a=candidate:1978755251 1 udp 2122260223 10.88.65.80 34027 typ host generation 0 network-id 1 network-cost 10 a=candidate:3702450022 1 udp 1686052607 50.246.121.173 34027 typ srflx raddr 10.88.65.80 rport 34027 generation 0 network-id 1 network-cost 10 a=candidate:3425785639 1 udp 41885439 18.204.23.155 61006 typ relay raddr 50.246.121.173 rport 34027 generation 0 network-id 1 network-cost 10 a=candidate:997364803 1 tcp 1518280447 10.88.65.80 9 typ host tcptype active generation 0 network-id 1 network-cost 10 a=ice-ufrag:EVJX a=ice-pwd:ppoOZcwEGehOPKMM03ol7g5r a=ice-options:trickle a=fingerprint:sha-256 37:F4:29:14:94:6A:87:51:7E:44:81:FA:71:BF:22:D7:71:0C:02:93:49:61:36:3A:A6:AA:B5:34:2B:CA:1F:55 a=setup:actpass a=mid:0 a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level a=extmap:2 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01 a=extmap:3 urn:ietf:params:rtp-hdrext:sdes:mid a=extmap:4 urn:ietf:params:rtp-hdrext:sdes:rtp-stream-id a=extmap:5 urn:ietf:params:rtp-hdrext:sdes:repaired-rtp-stream-id a=msid:DrxEOjCVvHNi3DtuKJs175ibnTtb2huY2WVc 4fdf8bec-c8e1-42d1-a872-db6864ef5ac2 a=rtcp-mux a=rtcp-fb:111 transport-cc a=ssrc:767982924 cname:D8OaexP97luPw4OL a=ssrc:767982924 msid:DrxEOjCVvHNi3DtuKJs175ibnTtb2huY2WVc 4fdf8bec-c8e1-42d1-a872-db6864ef5ac2 a=ssrc:767982924 mslabel:DrxEOjCVvHNi3DtuKJs175ibnTtb2huY2WVc a=ssrc:767982924 label:4fdf8bec-c8e1-42d1-a872-db6864ef5ac2 2019-09-30 20:27:36.531844 [DEBUG] sofia.c:7702 (sofia/internal/ beth@stage.illumy1.com) State Change CS_NEW -> CS_INIT 2019-09-30 20:27:36.531844 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/beth@stage.illumy1.com) Running State Change CS_INIT (Cur 3 Tot 925) 2019-09-30 20:27:36.531844 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/beth@stage.illumy1.com) State INIT 2019-09-30 20:27:36.531844 [DEBUG] mod_sofia.c:93 sofia/internal/ beth@stage.illumy1.com SOFIA INIT 2019-09-30 20:27:36.531844 [DEBUG] switch_core_state_machine.c:40 sofia/internal/beth@stage.illumy1.com Standard INIT 2019-09-30 20:27:36.531844 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/beth@stage.illumy1.com) State Change CS_INIT -> CS_ROUTING 2019-09-30 20:27:36.531844 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/beth@stage.illumy1.com) State INIT going to sleep 2019-09-30 20:27:36.531844 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/beth@stage.illumy1.com) Running State Change CS_ROUTING (Cur 3 Tot 925) 2019-09-30 20:27:36.531844 [DEBUG] switch_channel.c:2332 (sofia/internal/ beth@stage.illumy1.com) Callstate Change DOWN -> RINGING 2019-09-30 20:27:36.531844 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/beth@stage.illumy1.com) State ROUTING 2019-09-30 20:27:36.531844 [DEBUG] mod_sofia.c:154 sofia/internal/ beth@stage.illumy1.com SOFIA ROUTING 2019-09-30 20:27:36.531844 [DEBUG] switch_core_state_machine.c:236 sofia/internal/beth@stage.illumy1.com Standard ROUTING 2019-09-30 20:27:36.531844 [INFO] mod_dialplan_xml.c:637 Processing beth@stage.illumy1.com <beth>->nathan in context default send 352 bytes to wss/[50.246.121.173]:34010 at 20:27:36.543879: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/WSS vg5qpm92h7dm.invalid;branch=z9hG4bK9166577;received=50.246.121.173;rport=34010 From: "beth@stage.illumy1.com" <sip:beth@stage.illumy1.com>;tag=36ov91agi3 To: <sip:nathan@stage.illumy1.com> Call-ID: reo4dv21qm4aauclal7r CSeq: 2 INVITE User-Agent: FreeSWITCH-mod_sofia/1.10.0-release~64bit Content-Length: 0 Dialplan: sofia/internal/beth@stage.illumy1.com parsing [default->global] continue=true Dialplan: sofia/internal/beth@stage.illumy1.com Absolute Condition [global] Dialplan: sofia/internal/beth@stage.illumy1.com Action info() Dialplan: sofia/internal/beth@stage.illumy1.com parsing [default->Local_Users] continue=false Dialplan: sofia/internal/beth@stage.illumy1.com Regex (PASS) [Local_Users] destination_number(nathan) =~ /((?!^\d+$)^[a-zA-Z0-9_\-\.]+$)$/ break=on-false Dialplan: sofia/internal/beth@stage.illumy1.com Action set(continue_on_fail=false) Dialplan: sofia/internal/beth@stage.illumy1.com Action set(hangup_after_bridge=true) Dialplan: sofia/internal/beth@stage.illumy1.com Action set(bypass_media=true) Dialplan: sofia/internal/beth@stage.illumy1.com Action lua(endpoint_lookup.lua) Dialplan: sofia/internal/beth@stage.illumy1.com Action set(call_timeout=20) Dialplan: sofia/internal/beth@stage.illumy1.com Action bridge(${dial_to_string}) Dialplan: sofia/internal/beth@stage.illumy1.com Action set(bypass_media=false) Dialplan: sofia/internal/beth@stage.illumy1.com Action answer() Dialplan: sofia/internal/beth@stage.illumy1.com Action sleep(1000) Dialplan: sofia/internal/beth@stage.illumy1.com Action voicemail(${voicemail_string}) 2019-09-30 20:27:36.531844 [DEBUG] switch_core_state_machine.c:287 (sofia/internal/beth@stage.illumy1.com) State Change CS_ROUTING -> CS_EXECUTE 2019-09-30 20:27:36.531844 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/beth@stage.illumy1.com) State ROUTING going to sleep 2019-09-30 20:27:36.531844 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/beth@stage.illumy1.com) Running State Change CS_EXECUTE (Cur 3 Tot 925) 2019-09-30 20:27:36.531844 [DEBUG] switch_core_state_machine.c:651 (sofia/internal/beth@stage.illumy1.com) State EXECUTE 2019-09-30 20:27:36.531844 [DEBUG] mod_sofia.c:209 sofia/internal/ beth@stage.illumy1.com SOFIA EXECUTE 2019-09-30 20:27:36.531844 [DEBUG] switch_core_state_machine.c:329 sofia/internal/beth@stage.illumy1.com Standard EXECUTE EXECUTE [depth=0] sofia/internal/beth@stage.illumy1.com info() 2019-09-30 20:27:36.531844 [INFO] mod_dptools.c:1885 CHANNEL_DATA: Channel-State: [CS_EXECUTE] Channel-Call-State: [RINGING] Channel-State-Number: [4] Channel-Name: [sofia/internal/beth@stage.illumy1.com] Unique-ID: [59f602c8-5c38-4c8b-984f-7f09197e9fa3] Call-Direction: [inbound] Presence-Call-Direction: [inbound] Channel-HIT-Dialplan: [true] Channel-Presence-ID: [beth@stage.illumy1.com] Channel-Call-UUID: [59f602c8-5c38-4c8b-984f-7f09197e9fa3] Answer-State: [ringing] Caller-Direction: [inbound] Caller-Logical-Direction: [inbound] Caller-Username: [beth] Caller-Dialplan: [XML] Caller-Caller-ID-Name: [beth@stage.illumy1.com] Caller-Caller-ID-Number: [beth] Caller-Orig-Caller-ID-Name: [beth@stage.illumy1.com] Caller-Orig-Caller-ID-Number: [beth] Caller-Network-Addr: [50.246.121.173] Caller-ANI: [beth] Caller-Destination-Number: [nathan] Caller-Unique-ID: [59f602c8-5c38-4c8b-984f-7f09197e9fa3] Caller-Source: [mod_sofia] Caller-Context: [default] Caller-Channel-Name: [sofia/internal/beth@stage.illumy1.com] Caller-Profile-Index: [1] Caller-Profile-Created-Time: [1569875256531844] Caller-Channel-Created-Time: [1569875256531844] Caller-Channel-Answered-Time: [0] Caller-Channel-Progress-Time: [0] Caller-Channel-Progress-Media-Time: [0] Caller-Channel-Hangup-Time: [0] Caller-Channel-Transfer-Time: [0] Caller-Channel-Resurrect-Time: [0] Caller-Channel-Bridged-Time: [0] Caller-Channel-Last-Hold: [0] Caller-Channel-Hold-Accum: [0] Caller-Screen-Bit: [true] Caller-Privacy-Hide-Name: [false] Caller-Privacy-Hide-Number: [false] variable_direction: [inbound] variable_uuid: [59f602c8-5c38-4c8b-984f-7f09197e9fa3] variable_session_id: [925] variable_sip_from_user: [beth] variable_sip_from_uri: [beth@stage.illumy1.com] variable_sip_from_host: [stage.illumy1.com] variable_video_media_flow: [disabled] variable_audio_media_flow: [disabled] variable_text_media_flow: [disabled] variable_channel_name: [sofia/internal/beth@stage.illumy1.com] variable_sip_call_id: [reo4dv21qm4aauclal7r] variable_sip_local_network_addr: [18.211.78.106] variable_sip_network_ip: [50.246.121.173] variable_sip_network_port: [34010] variable_sip_invite_stamp: [1569875256511840] variable_sip_received_ip: [50.246.121.173] variable_sip_received_port: [34010] variable_sip_via_protocol: [wss] variable_sip_authorized: [true] variable_Event-Name: [REQUEST_PARAMS] variable_Core-UUID: [7e617e4b-996a-445f-a4d4-c6fc5db9b2cf] variable_FreeSWITCH-Hostname: [as1-east] variable_FreeSWITCH-Switchname: [as1-east] variable_FreeSWITCH-IPv4: [10.0.0.237] variable_FreeSWITCH-IPv6: [::1] variable_Event-Date-Local: [2019-09-30 20:27:36] variable_Event-Date-GMT: [Mon, 30 Sep 2019 20:27:36 GMT] variable_Event-Date-Timestamp: [1569875256511840] variable_Event-Calling-File: [sofia.c] variable_Event-Calling-Function: [sofia_handle_sip_i_invite] variable_Event-Calling-Line-Number: [10504] variable_Event-Sequence: [152629] variable_sip_number_alias: [beth] variable_sip_auth_username: [beth] variable_sip_auth_realm: [stage.illumy1.com] variable_number_alias: [beth] variable_requested_user_name: [beth] variable_requested_domain_name: [stage.illumy1.com] variable_user_context: [default] variable_effective_caller_id_name: [Beth User] variable_effective_caller_id_number: [beth] variable_outbound_caller_id_name: [Beth User] variable_user_name: [beth] variable_domain_name: [stage.illumy1.com] variable_sip_from_user_stripped: [beth] variable_sip_from_tag: [36ov91agi3] variable_sofia_profile_name: [internal] variable_sofia_profile_url: [sip:mod_sofia@18.211.78.106:5060] variable_recovery_profile_name: [internal] variable_sip_full_via: [SIP/2.0/WSS vg5qpm92h7dm.invalid;branch=z9hG4bK9166577;received=50.246.121.173;rport=34010] variable_sip_from_display: [beth@stage.illumy1.com] variable_sip_full_from: ["beth@stage.illumy1.com" < sip:beth@stage.illumy1.com>;tag=36ov91agi3] variable_sip_full_to: [<sip:nathan@stage.illumy1.com>] variable_sip_allow: [ACK, CANCEL, INVITE, MESSAGE, BYE, OPTIONS, INFO, NOTIFY, REFER] variable_sip_req_user: [nathan] variable_sip_req_uri: [nathan@stage.illumy1.com] variable_sip_req_host: [stage.illumy1.com] variable_sip_to_user: [nathan] variable_sip_to_uri: [nathan@stage.illumy1.com] variable_sip_to_host: [stage.illumy1.com] variable_sip_contact_params: [transport=ws;ob] variable_sip_contact_user: [0s9riicj] variable_sip_contact_uri: [0s9riicj@vg5qpm92h7dm.invalid] variable_sip_contact_host: [vg5qpm92h7dm.invalid] variable_rtp_use_codec_string: [OPUS,PCMU,VP8] variable_sip_user_agent: [beth@stage.illumy1.com] variable_sip_via_host: [vg5qpm92h7dm.invalid] variable_sip_via_rport: [34010] variable_max_forwards: [70] variable_presence_id: [beth@stage.illumy1.com] variable_sip_h_X-Foo: [true] variable_sip_nat_detected: [true] variable_switch_r_sdp: [v=0 o=- 3923831751587036465 2 IN IP4 127.0.0.1 s=- t=0 0 a=group:BUNDLE 0 a=msid-semantic: WMS DrxEOjCVvHNi3DtuKJs175ibnTtb2huY2WVc m=audio 61006 UDP/TLS/RTP/SAVPF 111 103 104 9 0 8 106 105 13 110 112 113 126 c=IN IP4 18.204.23.155 a=rtpmap:111 opus/48000/2 a=fmtp:111 minptime=10;useinbandfec=1 a=rtpmap:103 ISAC/16000 a=rtpmap:104 ISAC/32000 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:106 CN/32000 a=rtpmap:105 CN/16000 a=rtpmap:13 CN/8000 a=rtpmap:110 telephone-event/48000 a=rtpmap:112 telephone-event/32000 a=rtpmap:113 telephone-event/16000 a=rtpmap:126 telephone-event/8000 a=rtcp:9 IN IP4 0.0.0.0 a=candidate:1978755251 1 udp 2122260223 10.88.65.80 34027 typ host generation 0 network-id 1 network-cost 10 a=candidate:3702450022 1 udp 1686052607 50.246.121.173 34027 typ srflx raddr 10.88.65.80 rport 34027 generation 0 network-id 1 network-cost 10 a=candidate:3425785639 1 udp 41885439 18.204.23.155 61006 typ relay raddr 50.246.121.173 rport 34027 generation 0 network-id 1 network-cost 10 a=candidate:997364803 1 tcp 1518280447 10.88.65.80 9 typ host tcptype active generation 0 network-id 1 network-cost 10 a=ice-ufrag:EVJX a=ice-pwd:ppoOZcwEGehOPKMM03ol7g5r a=ice-options:trickle a=fingerprint:sha-256 37:F4:29:14:94:6A:87:51:7E:44:81:FA:71:BF:22:D7:71:0C:02:93:49:61:36:3A:A6:AA:B5:34:2B:CA:1F:55 a=setup:actpass a=mid:0 a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level a=extmap:2 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01 a=extmap:3 urn:ietf:params:rtp-hdrext:sdes:mid a=extmap:4 urn:ietf:params:rtp-hdrext:sdes:rtp-stream-id a=extmap:5 urn:ietf:params:rtp-hdrext:sdes:repaired-rtp-stream-id a=msid:DrxEOjCVvHNi3DtuKJs175ibnTtb2huY2WVc 4fdf8bec-c8e1-42d1-a872-db6864ef5ac2 a=rtcp-mux a=rtcp-fb:111 transport-cc a=ssrc:767982924 cname:D8OaexP97luPw4OL a=ssrc:767982924 msid:DrxEOjCVvHNi3DtuKJs175ibnTtb2huY2WVc 4fdf8bec-c8e1-42d1-a872-db6864ef5ac2 a=ssrc:767982924 mslabel:DrxEOjCVvHNi3DtuKJs175ibnTtb2huY2WVc a=ssrc:767982924 label:4fdf8bec-c8e1-42d1-a872-db6864ef5ac2 ] variable_ep_codec_string: [mod_opus.opus@48000h@20i@2c ,CORE_PCM_MODULE.PCMU@8000h@20i@64000b] variable_endpoint_disposition: [DELAYED NEGOTIATION] variable_DP_MATCH: [ARRAY::nathan|:nathan] variable_call_uuid: [59f602c8-5c38-4c8b-984f-7f09197e9fa3] variable_current_application: [info] EXECUTE [depth=0] sofia/internal/beth@stage.illumy1.com set(continue_on_fail=false) 2019-09-30 20:27:36.531844 [DEBUG] mod_dptools.c:1672 SET sofia/internal/ beth@stage.illumy1.com [continue_on_fail]=[false] EXECUTE [depth=0] sofia/internal/beth@stage.illumy1.com set(hangup_after_bridge=true) 2019-09-30 20:27:36.531844 [DEBUG] mod_dptools.c:1672 SET sofia/internal/ beth@stage.illumy1.com [hangup_after_bridge]=[true] EXECUTE [depth=0] sofia/internal/beth@stage.illumy1.com set(bypass_media=true) 2019-09-30 20:27:36.531844 [DEBUG] mod_dptools.c:1672 SET sofia/internal/ beth@stage.illumy1.com [bypass_media]=[true] EXECUTE [depth=0] sofia/internal/beth@stage.illumy1.com lua(endpoint_lookup.lua) 2019-09-30 20:27:36.591836 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('voicemail_string', 'default stage.illumy1.com nathan') 2019-09-30 20:27:36.591836 [INFO] switch_cpp.cpp:1443 SEARCH QUERY: SELECT server_host FROM sip_registrations WHERE sip_user = 'nathan' AND sip_host = 'stage.illumy1.com' AND ping_status = 'Reachable'; 2019-09-30 20:27:36.591836 [INFO] switch_cpp.cpp:1443 FOUND AT HOST: 10.0.0.12 2019-09-30 20:27:36.591836 [INFO] switch_cpp.cpp:1443 FOUND AT HOST: 10.0.0.237 2019-09-30 20:27:36.591836 [INFO] switch_cpp.cpp:1443 User's nathan@stage.illumy1.com toll_allow value is <voicemail> 2019-09-30 20:27:36.591836 [INFO] switch_cpp.cpp:1443 Voicemail enabled 2019-09-30 20:27:36.591836 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('continue_on_fail', 'true') 2019-09-30 20:27:36.591836 [INFO] switch_cpp.cpp:1443 ADDING HOST: 10.0.0.12 TO DIAL STRING 2019-09-30 20:27:36.591836 [INFO] switch_cpp.cpp:1443 REMOTE REGISTERED USER! 2019-09-30 20:27:36.591836 [INFO] switch_cpp.cpp:1443 ADDING HOST: 10.0.0.237 TO DIAL STRING 2019-09-30 20:27:36.591836 [INFO] switch_cpp.cpp:1443 LOCAL REGISTERED USER! 2019-09-30 20:27:36.591836 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('dial_to_string', '[sip_h_X-voicemailed=true,sip_h_X-local-call=true,sip_invite_domain= stage.illumy1.com]sofia/external/nathan@10.0.0.12:5080,${sofia_contact( nathan@stage.illumy1.com)}') 2019-09-30 20:27:36.591836 [DEBUG] switch_cpp.cpp:1187 sofia/internal/ beth@stage.illumy1.com destroy/unlink session from object EXECUTE [depth=0] sofia/internal/beth@stage.illumy1.com set(call_timeout=20) 2019-09-30 20:27:36.591836 [DEBUG] mod_dptools.c:1672 SET sofia/internal/ beth@stage.illumy1.com [call_timeout]=[20] EXECUTE [depth=0] sofia/internal/beth@stage.illumy1.com bridge([sip_h_X-voicemailed=true,sip_h_X-local-call=true,sip_invite_domain= stage.illumy1.com]sofia/external/nathan@10.0.0.12:5080 ,sofia/internal/sip:j7fd3415@geutlen0uga7.invalid ;transport=ws;received=50.246.121.173:39318 ;fs_nat=yes;fs_path=sip%3Aj7fd3415%4050.246.121.173%3A39318%3Btransport%3Dwss,sofia/internal/sip:r6ucrocm@3val7ifjblg6.invalid ;transport=ws;received=50.246.121.173:34738 ;fs_nat=yes;fs_path=sip%3Ar6ucrocm%4050.246.121.173%3A34738%3Btransport%3Dwss) 2019-09-30 20:27:36.591836 [DEBUG] switch_ivr_originate.c:2212 Parsing global variables 2019-09-30 20:27:36.591836 [DEBUG] switch_ivr_originate.c:2757 Parsing session specific variables 2019-09-30 20:27:36.591836 [NOTICE] switch_channel.c:1118 New Channel sofia/external/nathan@10.0.0.12:5080 [971aae94-0463-4c9f-809d-10dfbcb265bc] 2019-09-30 20:27:36.591836 [DEBUG] mod_sofia.c:5096 (sofia/external/ nathan@10.0.0.12:5080) State Change CS_NEW -> CS_INIT 2019-09-30 20:27:36.591836 [DEBUG] switch_core_state_machine.c:585 (sofia/external/nathan@10.0.0.12:5080) Running State Change CS_INIT (Cur 4 Tot 926) 2019-09-30 20:27:36.591836 [DEBUG] switch_core_state_machine.c:628 (sofia/external/nathan@10.0.0.12:5080) State INIT 2019-09-30 20:27:36.591836 [DEBUG] mod_sofia.c:93 sofia/external/ nathan@10.0.0.12:5080 SOFIA INIT 2019-09-30 20:27:36.591836 [NOTICE] switch_channel.c:1118 New Channel sofia/internal/j7fd3415@geutlen0uga7.invalid [83e36ab7-8275-4a5e-9afd-f9356da57b06] 2019-09-30 20:27:36.591836 [DEBUG] mod_sofia.c:5096 (sofia/internal/j7fd3415@geutlen0uga7.invalid) State Change CS_NEW -> CS_INIT 2019-09-30 20:27:36.591836 [DEBUG] sofia_glue.c:1618 sofia/external/ nathan@10.0.0.12:5080 sending invite version: 1.10.0 -release 64bit Local SDP: v=0 o=- 3923831751587036465 2 IN IP4 127.0.0.1 s=- t=0 0 a=group:BUNDLE 0 a=msid-semantic: WMS DrxEOjCVvHNi3DtuKJs175ibnTtb2huY2WVc m=audio 61006 UDP/TLS/RTP/SAVPF 111 103 104 9 0 8 106 105 13 110 112 113 126 c=IN IP4 18.204.23.155 a=rtpmap:111 opus/48000/2 a=fmtp:111 minptime=10;useinbandfec=1 a=rtpmap:103 ISAC/16000 a=rtpmap:104 ISAC/32000 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:106 CN/32000 a=rtpmap:105 CN/16000 a=rtpmap:13 CN/8000 a=rtpmap:110 telephone-event/48000 a=rtpmap:112 telephone-event/32000 a=rtpmap:113 telephone-event/16000 a=rtpmap:126 telephone-event/8000 a=rtcp:9 IN IP4 0.0.0.0 a=candidate:1978755251 1 udp 2122260223 10.88.65.80 34027 typ host generation 0 network-id 1 network-cost 10 a=candidate:3702450022 1 udp 1686052607 50.246.121.173 34027 typ srflx raddr 10.88.65.80 rport 34027 generation 0 network-id 1 network-cost 10 a=candidate:3425785639 1 udp 41885439 18.204.23.155 61006 typ relay raddr 50.246.121.173 rport 34027 generation 0 network-id 1 network-cost 10 a=candidate:997364803 1 tcp 1518280447 10.88.65.80 9 typ host tcptype active generation 0 network-id 1 network-cost 10 a=ice-ufrag:EVJX a=ice-pwd:ppoOZcwEGehOPKMM03ol7g5r a=ice-options:trickle a=fingerprint:sha-256 37:F4:29:14:94:6A:87:51:7E:44:81:FA:71:BF:22:D7:71:0C:02:93:49:61:36:3A:A6:AA:B5:34:2B:CA:1F:55 a=setup:actpass a=mid:0 a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level a=extmap:2 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01 a=extmap:3 urn:ietf:params:rtp-hdrext:sdes:mid a=extmap:4 urn:ietf:params:rtp-hdrext:sdes:rtp-stream-id a=extmap:5 urn:ietf:params:rtp-hdrext:sdes:repaired-rtp-stream-id a=msid:DrxEOjCVvHNi3DtuKJs175ibnTtb2huY2WVc 4fdf8bec-c8e1-42d1-a872-db6864ef5ac2 a=rtcp-mux a=rtcp-fb:111 transport-cc a=ssrc:767982924 cname:D8OaexP97luPw4OL a=ssrc:767982924 msid:DrxEOjCVvHNi3DtuKJs175ibnTtb2huY2WVc 4fdf8bec-c8e1-42d1-a872-db6864ef5ac2 a=ssrc:767982924 mslabel:DrxEOjCVvHNi3DtuKJs175ibnTtb2huY2WVc a=ssrc:767982924 label:4fdf8bec-c8e1-42d1-a872-db6864ef5ac2 2019-09-30 20:27:36.591836 [NOTICE] switch_channel.c:1118 New Channel sofia/internal/r6ucrocm@3val7ifjblg6.invalid [56c0cd2d-e19b-4c45-a278-81ed26d09636] 2019-09-30 20:27:36.591836 [DEBUG] mod_sofia.c:5096 (sofia/internal/r6ucrocm@3val7ifjblg6.invalid) State Change CS_NEW -> CS_INIT send 2935 bytes to udp/[10.0.0.12]:5080 at 20:27:36.605793: ------------------------------------------------------------------------ INVITE sip:nathan@10.0.0.12:5080 SIP/2.0 Via: SIP/2.0/UDP 10.0.0.237:5080;rport;branch=z9hG4bKHmc9rvvg1aUeQ Max-Forwards: 69 From: "Beth User" <sip:beth@stage.illumy1.com>;tag=UXNaNXZpme5SD To: <sip:nathan@10.0.0.12:5080> Call-ID: 94fd528d-5e63-1238-2787-0251a831415e CSeq: 10383836 INVITE Contact: <sip:mod_sofia@10.0.0.237:5080> User-Agent: FreeSWITCH-mod_sofia/1.10.0-release~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Content-Type: application/sdp Content-Disposition: session Content-Length: 2097 X-Foo: true X-voicemailed: true X-local-call: true X-FS-Support: update_display,send_info Remote-Party-ID: "Beth User" <sip:beth@stage.illumy1.com
;party=calling;screen=yes;privacy=off
v=0 o=- 3923831751587036465 2 IN IP4 10.0.0.237 s=- t=0 0 a=group:BUNDLE 0 a=msid-semantic: WMS DrxEOjCVvHNi3DtuKJs175ibnTtb2huY2WVc m=audio 61006 UDP/TLS/RTP/SAVPF 111 103 104 9 0 8 106 105 13 110 112 113 126 c=IN IP4 18.204.23.155 a=rtpmap:111 opus/48000/2 a=fmtp:111 minptime=10;useinbandfec=1 a=rtpmap:103 ISAC/16000 a=rtpmap:104 ISAC/32000 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:106 CN/32000 a=rtpmap:105 CN/16000 a=rtpmap:13 CN/8000 a=rtpmap:110 telephone-event/48000 a=rtpmap:112 telephone-event/32000 a=rtpmap:113 telephone-event/16000 a=rtpmap:126 telephone-event/8000 a=rtcp:9 IN IP4 0.0.0.0 a=candidate:1978755251 1 udp 2122260223 10.88.65.80 34027 typ host generation 0 network-id 1 network-cost 10 a=candidate:3702450022 1 udp 1686052607 50.246.121.173 34027 typ srflx raddr 10.88.65.80 rport 34027 generation 0 network-id 1 network-cost 10 a=candidate:3425785639 1 udp 41885439 18.204.23.155 61006 typ relay raddr 50.246.121.173 rport 34027 generation 0 network-id 1 network-cost 10 a=candidate:997364803 1 tcp 1518280447 10.88.65.80 9 typ host tcptype active generation 0 network-id 1 network-cost 10 a=ice-ufrag:EVJX a=ice-pwd:ppoOZcwEGehOPKMM03ol7g5r a=ice-options:trickle a=fingerprint:sha-256 37:F4:29:14:94:6A:87:51:7E:44:81:FA:71:BF:22:D7:71:0C:02:93:49:61:36:3A:A6:AA:B5:34:2B:CA:1F:55 a=setup:actpass a=mid:0 a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level a=extmap:2 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01 a=extmap:3 urn:ietf:params:rtp-hdrext:sdes:mid a=extmap:4 urn:ietf:params:rtp-hdrext:sdes:rtp-stream-id a=extmap:5 urn:ietf:params:rtp-hdrext:sdes:repaired-rtp-stream-id a=msid:DrxEOjCVvHNi3DtuKJs175ibnTtb2huY2WVc 4fdf8bec-c8e1-42d1-a872-db6864ef5ac2 a=rtcp-mux a=rtcp-fb:111 transport-cc a=ssrc:767982924 cname:D8OaexP97luPw4OL a=ssrc:767982924 msid:DrxEOjCVvHNi3DtuKJs175ibnTtb2huY2WVc 4fdf8bec-c8e1-42d1-a872-db6864ef5ac2 a=ssrc:767982924 mslabel:DrxEOjCVvHNi3DtuKJs175ibnTtb2huY2WVc a=ssrc:767982924 label:4fdf8bec-c8e1-42d1-a872-db6864ef5ac2 2019-09-30 20:27:36.591836 [DEBUG] switch_core_state_machine.c:40 sofia/external/nathan@10.0.0.12:5080 Standard INIT 2019-09-30 20:27:36.591836 [DEBUG] switch_core_state_machine.c:48 (sofia/external/nathan@10.0.0.12:5080) State Change CS_INIT -> CS_ROUTING 2019-09-30 20:27:36.591836 [DEBUG] switch_core_state_machine.c:628 (sofia/external/nathan@10.0.0.12:5080) State INIT going to sleep 2019-09-30 20:27:36.591836 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/j7fd3415@geutlen0uga7.invalid) Running State Change CS_INIT (Cur 6 Tot 928) 2019-09-30 20:27:36.591836 [DEBUG] switch_core_state_machine.c:585 (sofia/external/nathan@10.0.0.12:5080) Running State Change CS_ROUTING (Cur 6 Tot 928) 2019-09-30 20:27:36.591836 [DEBUG] sofia.c:7289 Channel sofia/external/ nathan@10.0.0.12:5080 entering state [calling][0] 2019-09-30 20:27:36.591836 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/j7fd3415@geutlen0uga7.invalid) State INIT 2019-09-30 20:27:36.591836 [DEBUG] mod_sofia.c:93 sofia/internal/j7fd3415@geutlen0uga7.invalid SOFIA INIT 2019-09-30 20:27:36.591836 [DEBUG] sofia.c:7289 Channel sofia/external/ nathan@10.0.0.12:5080 entering state [terminated][503] 2019-09-30 20:27:36.591836 [NOTICE] sofia.c:8522 Hangup sofia/external/ nathan@10.0.0.12:5080 [CS_ROUTING] [NORMAL_TEMPORARY_FAILURE] 2019-09-30 20:27:36.591836 [DEBUG] switch_core_state_machine.c:644 (sofia/external/nathan@10.0.0.12:5080) State ROUTING 2019-09-30 20:27:36.591836 [DEBUG] mod_sofia.c:154 sofia/external/ nathan@10.0.0.12:5080 SOFIA ROUTING 2019-09-30 20:27:36.591836 [DEBUG] switch_core_state_machine.c:644 (sofia/external/nathan@10.0.0.12:5080) State ROUTING going to sleep 2019-09-30 20:27:36.591836 [DEBUG] switch_core_state_machine.c:585 (sofia/external/nathan@10.0.0.12:5080) Running State Change CS_HANGUP (Cur 6 Tot 928) 2019-09-30 20:27:36.591836 [DEBUG] sofia_glue.c:1587 sip:j7fd3415@50.246.121.173:39318;transport=wss Setting proxy route to sofia/internal/j7fd3415@geutlen0uga7.invalid 2019-09-30 20:27:36.591836 [DEBUG] sofia_glue.c:1618 sofia/internal/j7fd3415@geutlen0uga7.invalid sending invite version: 1.10.0 -release 64bit Local SDP: v=0 o=- 3923831751587036465 2 IN IP4 127.0.0.1 s=- t=0 0 a=group:BUNDLE 0 a=msid-semantic: WMS DrxEOjCVvHNi3DtuKJs175ibnTtb2huY2WVc m=audio 61006 UDP/TLS/RTP/SAVPF 111 103 104 9 0 8 106 105 13 110 112 113 126 c=IN IP4 18.204.23.155 a=rtpmap:111 opus/48000/2 a=fmtp:111 minptime=10;useinbandfec=1 a=rtpmap:103 ISAC/16000 a=rtpmap:104 ISAC/32000 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:106 CN/32000 a=rtpmap:105 CN/16000 a=rtpmap:13 CN/8000 a=rtpmap:110 telephone-event/48000 a=rtpmap:112 telephone-event/32000 a=rtpmap:113 telephone-event/16000 a=rtpmap:126 telephone-event/8000 a=rtcp:9 IN IP4 0.0.0.0 a=candidate:1978755251 1 udp 2122260223 10.88.65.80 34027 typ host generation 0 network-id 1 network-cost 10 a=candidate:3702450022 1 udp 1686052607 50.246.121.173 34027 typ srflx raddr 10.88.65.80 rport 34027 generation 0 network-id 1 network-cost 10 a=candidate:3425785639 1 udp 41885439 18.204.23.155 61006 typ relay raddr 50.246.121.173 rport 34027 generation 0 network-id 1 network-cost 10 a=candidate:997364803 1 tcp 1518280447 10.88.65.80 9 typ host tcptype active generation 0 network-id 1 network-cost 10 a=ice-ufrag:EVJX a=ice-pwd:ppoOZcwEGehOPKMM03ol7g5r a=ice-options:trickle a=fingerprint:sha-256 37:F4:29:14:94:6A:87:51:7E:44:81:FA:71:BF:22:D7:71:0C:02:93:49:61:36:3A:A6:AA:B5:34:2B:CA:1F:55 a=setup:actpass a=mid:0 a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level a=extmap:2 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01 a=extmap:3 urn:ietf:params:rtp-hdrext:sdes:mid a=extmap:4 urn:ietf:params:rtp-hdrext:sdes:rtp-stream-id a=extmap:5 urn:ietf:params:rtp-hdrext:sdes:repaired-rtp-stream-id a=msid:DrxEOjCVvHNi3DtuKJs175ibnTtb2huY2WVc 4fdf8bec-c8e1-42d1-a872-db6864ef5ac2 a=rtcp-mux a=rtcp-fb:111 transport-cc a=ssrc:767982924 cname:D8OaexP97luPw4OL a=ssrc:767982924 msid:DrxEOjCVvHNi3DtuKJs175ibnTtb2huY2WVc 4fdf8bec-c8e1-42d1-a872-db6864ef5ac2 a=ssrc:767982924 mslabel:DrxEOjCVvHNi3DtuKJs175ibnTtb2huY2WVc a=ssrc:767982924 label:4fdf8bec-c8e1-42d1-a872-db6864ef5ac2 2019-09-30 20:27:36.591836 [DEBUG] switch_core_state_machine.c:848 (sofia/external/nathan@10.0.0.12:5080) Callstate Change DOWN -> HANGUP 2019-09-30 20:27:36.591836 [DEBUG] switch_core_state_machine.c:850 (sofia/external/nathan@10.0.0.12:5080) State HANGUP 2019-09-30 20:27:36.591836 [DEBUG] mod_sofia.c:460 Channel sofia/external/ nathan@10.0.0.12:5080 hanging up, cause: NORMAL_TEMPORARY_FAILURE 2019-09-30 20:27:36.591836 [DEBUG] switch_core_state_machine.c:60 sofia/external/nathan@10.0.0.12:5080 Standard HANGUP, cause: NORMAL_TEMPORARY_FAILURE 2019-09-30 20:27:36.591836 [DEBUG] switch_core_state_machine.c:850 (sofia/external/nathan@10.0.0.12:5080) State HANGUP going to sleep 2019-09-30 20:27:36.591836 [DEBUG] switch_core_state_machine.c:620 (sofia/external/nathan@10.0.0.12:5080) State Change CS_HANGUP -> CS_REPORTING 2019-09-30 20:27:36.591836 [DEBUG] switch_core_state_machine.c:585 (sofia/external/nathan@10.0.0.12:5080) Running State Change CS_REPORTING (Cur 6 Tot 928) 2019-09-30 20:27:36.591836 [DEBUG] switch_core_state_machine.c:936 (sofia/external/nathan@10.0.0.12:5080) State REPORTING 2019-09-30 20:27:36.591836 [DEBUG] mod_odbc_cdr.c:345 sql INSERT INTO cdr_table_both (CallId) VALUES ('971aae94-0463-4c9f-809d-10dfbcb265bc') 2019-09-30 20:27:36.591836 [DEBUG] switch_core_state_machine.c:40 sofia/internal/j7fd3415@geutlen0uga7.invalid Standard INIT 2019-09-30 20:27:36.591836 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/j7fd3415@geutlen0uga7.invalid) State Change CS_INIT -> CS_ROUTING 2019-09-30 20:27:36.591836 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/j7fd3415@geutlen0uga7.invalid) State INIT going to sleep 2019-09-30 20:27:36.591836 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/j7fd3415@geutlen0uga7.invalid) Running State Change CS_ROUTING (Cur 6 Tot 928) 2019-09-30 20:27:36.591836 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/j7fd3415@geutlen0uga7.invalid) State ROUTING 2019-09-30 20:27:36.591836 [DEBUG] mod_sofia.c:154 sofia/internal/j7fd3415@geutlen0uga7.invalid SOFIA ROUTING 2019-09-30 20:27:36.591836 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/j7fd3415@geutlen0uga7.invalid) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2019-09-30 20:27:36.591836 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/j7fd3415@geutlen0uga7.invalid) State ROUTING going to sleep 2019-09-30 20:27:36.591836 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/j7fd3415@geutlen0uga7.invalid) Running State Change CS_CONSUME_MEDIA (Cur 6 Tot 928) 2019-09-30 20:27:36.591836 [DEBUG] switch_core_state_machine.c:663 (sofia/internal/j7fd3415@geutlen0uga7.invalid) State CONSUME_MEDIA 2019-09-30 20:27:36.591836 [DEBUG] switch_core_state_machine.c:663 (sofia/internal/j7fd3415@geutlen0uga7.invalid) State CONSUME_MEDIA going to sleep 2019-09-30 20:27:36.591836 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/r6ucrocm@3val7ifjblg6.invalid) Running State Change CS_INIT (Cur 6 Tot 928) 2019-09-30 20:27:36.591836 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/r6ucrocm@3val7ifjblg6.invalid) State INIT 2019-09-30 20:27:36.591836 [DEBUG] mod_sofia.c:93 sofia/internal/r6ucrocm@3val7ifjblg6.invalid SOFIA INIT 2019-09-30 20:27:36.591836 [DEBUG] sofia_glue.c:1587 sip:r6ucrocm@50.246.121.173:34738;transport=wss Setting proxy route to sofia/internal/r6ucrocm@3val7ifjblg6.invalid 2019-09-30 20:27:36.591836 [DEBUG] sofia_glue.c:1618 sofia/internal/r6ucrocm@3val7ifjblg6.invalid sending invite version: 1.10.0 -release 64bit Local SDP: v=0 o=- 3923831751587036465 2 IN IP4 127.0.0.1 s=- t=0 0 a=group:BUNDLE 0 a=msid-semantic: WMS DrxEOjCVvHNi3DtuKJs175ibnTtb2huY2WVc m=audio 61006 UDP/TLS/RTP/SAVPF 111 103 104 9 0 8 106 105 13 110 112 113 126 c=IN IP4 18.204.23.155 a=rtpmap:111 opus/48000/2 a=fmtp:111 minptime=10;useinbandfec=1 a=rtpmap:103 ISAC/16000 a=rtpmap:104 ISAC/32000 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:106 CN/32000 a=rtpmap:105 CN/16000 a=rtpmap:13 CN/8000 a=rtpmap:110 telephone-event/48000 a=rtpmap:112 telephone-event/32000 a=rtpmap:113 telephone-event/16000 a=rtpmap:126 telephone-event/8000 a=rtcp:9 IN IP4 0.0.0.0 a=candidate:1978755251 1 udp 2122260223 10.88.65.80 34027 typ host generation 0 network-id 1 network-cost 10 a=candidate:3702450022 1 udp 1686052607 50.246.121.173 34027 typ srflx raddr 10.88.65.80 rport 34027 generation 0 network-id 1 network-cost 10 a=candidate:3425785639 1 udp 41885439 18.204.23.155 61006 typ relay raddr 50.246.121.173 rport 34027 generation 0 network-id 1 network-cost 10 a=candidate:997364803 1 tcp 1518280447 10.88.65.80 9 typ host tcptype active generation 0 network-id 1 network-cost 10 a=ice-ufrag:EVJX a=ice-pwd:ppoOZcwEGehOPKMM03ol7g5r a=ice-options:trickle a=fingerprint:sha-256 37:F4:29:14:94:6A:87:51:7E:44:81:FA:71:BF:22:D7:71:0C:02:93:49:61:36:3A:A6:AA:B5:34:2B:CA:1F:55 a=setup:actpass a=mid:0 a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level a=extmap:2 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01 a=extmap:3 urn:ietf:params:rtp-hdrext:sdes:mid a=extmap:4 urn:ietf:params:rtp-hdrext:sdes:rtp-stream-id a=extmap:5 urn:ietf:params:rtp-hdrext:sdes:repaired-rtp-stream-id a=msid:DrxEOjCVvHNi3DtuKJs175ibnTtb2huY2WVc 4fdf8bec-c8e1-42d1-a872-db6864ef5ac2 a=rtcp-mux a=rtcp-fb:111 transport-cc a=ssrc:767982924 cname:D8OaexP97luPw4OL a=ssrc:767982924 msid:DrxEOjCVvHNi3DtuKJs175ibnTtb2huY2WVc 4fdf8bec-c8e1-42d1-a872-db6864ef5ac2 a=ssrc:767982924 mslabel:DrxEOjCVvHNi3DtuKJs175ibnTtb2huY2WVc a=ssrc:767982924 label:4fdf8bec-c8e1-42d1-a872-db6864ef5ac2 2019-09-30 20:27:36.591836 [DEBUG] switch_core_state_machine.c:40 sofia/internal/r6ucrocm@3val7ifjblg6.invalid Standard INIT 2019-09-30 20:27:36.591836 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/r6ucrocm@3val7ifjblg6.invalid) State Change CS_INIT -> CS_ROUTING 2019-09-30 20:27:36.591836 [DEBUG] switch_core_state_machine.c:628 (sofia/internal/r6ucrocm@3val7ifjblg6.invalid) State INIT going to sleep 2019-09-30 20:27:36.591836 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/r6ucrocm@3val7ifjblg6.invalid) Running State Change CS_ROUTING (Cur 6 Tot 928) 2019-09-30 20:27:36.591836 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/r6ucrocm@3val7ifjblg6.invalid) State ROUTING 2019-09-30 20:27:36.591836 [DEBUG] mod_sofia.c:154 sofia/internal/r6ucrocm@3val7ifjblg6.invalid SOFIA ROUTING 2019-09-30 20:27:36.591836 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/r6ucrocm@3val7ifjblg6.invalid) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2019-09-30 20:27:36.591836 [DEBUG] switch_core_state_machine.c:644 (sofia/internal/r6ucrocm@3val7ifjblg6.invalid) State ROUTING going to sleep 2019-09-30 20:27:36.591836 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/r6ucrocm@3val7ifjblg6.invalid) Running State Change CS_CONSUME_MEDIA (Cur 6 Tot 928) 2019-09-30 20:27:36.591836 [DEBUG] switch_core_state_machine.c:663 (sofia/internal/r6ucrocm@3val7ifjblg6.invalid) State CONSUME_MEDIA 2019-09-30 20:27:36.591836 [DEBUG] switch_core_state_machine.c:663 (sofia/internal/r6ucrocm@3val7ifjblg6.invalid) State CONSUME_MEDIA going to sleep 2019-09-30 20:27:36.591836 [DEBUG] mod_odbc_cdr.c:345 sql INSERT INTO cdr_table_b_leg (CallId, orig_id, term_id, ClientId) VALUES ('59f602c8-5c38-4c8b-984f-7f09197e9fa3', '971aae94-0463-4c9f-809d-10dfbcb265bc', '94fd528d-5e63-1238-2787-0251a831415e', '971aae94-0463-4c9f-809d-10dfbcb265bc') 2019-09-30 20:27:36.591836 [DEBUG] sofia.c:7289 Channel sofia/internal/j7fd3415@geutlen0uga7.invalid entering state [calling][0] send 3150 bytes to wss/[50.246.121.173]:34738 at 20:27:36.611364: ------------------------------------------------------------------------ INVITE sip:r6ucrocm@3val7ifjblg6.invalid;transport=ws;received= 50.246.121.173:34738 SIP/2.0 Via: SIP/2.0/WSS 18.211.78.106:443;rport;branch=z9hG4bKye2ergXZB23jK Route: <sip:r6ucrocm@50.246.121.173:34738>;transport=wss Max-Forwards: 69 From: "Beth User" <sip:beth@18.211.78.106>;tag=yHm5UmrgvjmeN To: <sip:r6ucrocm@3val7ifjblg6.invalid;transport=ws;received= 50.246.121.173:34738> Call-ID: 94fe2e19-5e63-1238-2787-0251a831415e CSeq: 10383836 INVITE Contact: <sip:mod_sofia@18.211.78.106:5060> User-Agent: FreeSWITCH-mod_sofia/1.10.0-release~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: path, replaces Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Content-Type: application/sdp Content-Disposition: session Content-Length: 2097 X-Foo: true Remote-Party-ID: "Beth User" <sip:beth@18.211.78.106
;party=calling;screen=yes;privacy=off
v=0 o=- 3923831751587036465 2 IN IP4 10.0.0.237 s=- t=0 0 a=group:BUNDLE 0 a=msid-semantic: WMS DrxEOjCVvHNi3DtuKJs175ibnTtb2huY2WVc m=audio 61006 UDP/TLS/RTP/SAVPF 111 103 104 9 0 8 106 105 13 110 112 113 126 c=IN IP4 18.204.23.155 a=rtpmap:111 opus/48000/2 a=fmtp:111 minptime=10;useinbandfec=1 a=rtpmap:103 ISAC/16000 a=rtpmap:104 ISAC/32000 a=rtpmap:9 G722/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:106 CN/32000 a=rtpmap:105 CN/16000 a=rtpmap:13 CN/8000 a=rtpmap:110 telephone-event/48000 a=rtpmap:112 telephone-event/32000 a=rtpmap:113 telephone-event/16000 a=rtpmap:126 telephone-event/8000 a=rtcp:9 IN IP4 0.0.0.0 a=candidate:1978755251 1 udp 2122260223 10.88.65.80 34027 typ host generation 0 network-id 1 network-cost 10 a=candidate:3702450022 1 udp 1686052607 50.246.121.173 34027 typ srflx raddr 10.88.65.80 rport 34027 generation 0 network-id 1 network-cost 10 a=candidate:3425785639 1 udp 41885439 18.204.23.155 61006 typ relay raddr 50.246.121.173 rport 34027 generation 0 network-id 1 network-cost 10 a=candidate:997364803 1 tcp 1518280447 10.88.65.80 9 typ host tcptype active generation 0 network-id 1 network-cost 10 a=ice-ufrag:EVJX a=ice-pwd:ppoOZcwEGehOPKMM03ol7g5r a=ice-options:trickle a=fingerprint:sha-256 37:F4:29:14:94:6A:87:51:7E:44:81:FA:71:BF:22:D7:71:0C:02:93:49:61:36:3A:A6:AA:B5:34:2B:CA:1F:55 a=setup:actpass a=mid:0 a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level a=extmap:2 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01 a=extmap:3 urn:ietf:params:rtp-hdrext:sdes:mid a=extmap:4 urn:ietf:params:rtp-hdrext:sdes:rtp-stream-id a=extmap:5 urn:ietf:params:rtp-hdrext:sdes:repaired-rtp-stream-id a=msid:DrxEOjCVvHNi3DtuKJs175ibnTtb2huY2WVc 4fdf8bec-c8e1-42d1-a872-db6864ef5ac2 a=rtcp-mux a=rtcp-fb:111 transport-cc a=ssrc:767982924 cname:D8OaexP97luPw4OL a=ssrc:767982924 msid:DrxEOjCVvHNi3DtuKJs175ibnTtb2huY2WVc 4fdf8bec-c8e1-42d1-a872-db6864ef5ac2 a=ssrc:767982924 mslabel:DrxEOjCVvHNi3DtuKJs175ibnTtb2huY2WVc a=ssrc:767982924 label:4fdf8bec-c8e1-42d1-a872-db6864ef5ac2 2019-09-30 20:27:36.591836 [DEBUG] sofia.c:7289 Channel sofia/internal/r6ucrocm@3val7ifjblg6.invalid entering state [calling][0] 2019-09-30 20:27:36.611834 [DEBUG] switch_core_state_machine.c:174 sofia/external/nathan@10.0.0.12:5080 Standard REPORTING, cause: NORMAL_TEMPORARY_FAILURE 2019-09-30 20:27:36.611834 [DEBUG] switch_core_state_machine.c:936 (sofia/external/nathan@10.0.0.12:5080) State REPORTING going to sleep 2019-09-30 20:27:36.611834 [DEBUG] switch_core_state_machine.c:611 (sofia/external/nathan@10.0.0.12:5080) State Change CS_REPORTING -> CS_DESTROY 2019-09-30 20:27:36.611834 [DEBUG] switch_core_session.c:1726 Session 926 (sofia/external/nathan@10.0.0.12:5080) Locked, Waiting on external entities recv 386 bytes from wss/[50.246.121.173]:34738 at 20:27:36.651849: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/WSS 18.211.78.106:443;rport;branch=z9hG4bKye2ergXZB23jK From: "Beth User" <sip:beth@18.211.78.106>;tag=yHm5UmrgvjmeN To: <sip:r6ucrocm@3val7ifjblg6.invalid;transport=ws;received= 50.246.121.173:34738> CSeq: 10383836 INVITE Call-ID: 94fe2e19-5e63-1238-2787-0251a831415e Supported: outbound User-Agent: nathan@stage.illumy1.com Content-Length: 0 recv 461 bytes from wss/[50.246.121.173]:34738 at 20:27:36.656498: ------------------------------------------------------------------------ SIP/2.0 180 Ringing Via: SIP/2.0/WSS 18.211.78.106:443;rport;branch=z9hG4bKye2ergXZB23jK From: "Beth User" <sip:beth@18.211.78.106>;tag=yHm5UmrgvjmeN To: <sip:r6ucrocm@3val7ifjblg6.invalid;transport=ws;received= 50.246.121.173:34738>;tag=9eibedbcg9 CSeq: 10383836 INVITE Call-ID: 94fe2e19-5e63-1238-2787-0251a831415e Supported: outbound User-Agent: nathan@stage.illumy1.com Contact: <sip:r6ucrocm@3val7ifjblg6.invalid;transport=ws> Content-Length: 0 2019-09-30 20:27:36.651842 [DEBUG] sofia.c:7289 Channel sofia/internal/r6ucrocm@3val7ifjblg6.invalid entering state [proceeding][180] 2019-09-30 20:27:36.651842 [NOTICE] sofia.c:7400 Ring-Ready sofia/internal/r6ucrocm@3val7ifjblg6.invalid! 2019-09-30 20:27:36.651842 [NOTICE] mod_sofia.c:2505 Ring-Ready sofia/internal/beth@stage.illumy1.com! send 760 bytes to wss/[50.246.121.173]:34010 at 20:27:36.666536: ------------------------------------------------------------------------ SIP/2.0 180 Ringing Via: SIP/2.0/WSS vg5qpm92h7dm.invalid;branch=z9hG4bK9166577;received=50.246.121.173;rport=34010 From: "beth@stage.illumy1.com" <sip:beth@stage.illumy1.com>;tag=36ov91agi3 To: <sip:nathan@stage.illumy1.com>;tag=vZ1Kryp91078D Call-ID: reo4dv21qm4aauclal7r CSeq: 2 INVITE Contact: <sip:nathan@18.211.78.106:5060;transport=udp> User-Agent: FreeSWITCH-mod_sofia/1.10.0-release~64bit Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: path, replaces Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Content-Length: 0 2019-09-30 20:27:36.651842 [DEBUG] switch_channel.c:3437 (sofia/internal/r6ucrocm@3val7ifjblg6.invalid) Callstate Change DOWN -> RINGING 2019-09-30 20:27:36.651842 [DEBUG] sofia.c:7289 Channel sofia/internal/ beth@stage.illumy1.com entering state [early][180] 2019-09-30 20:27:36.651842 [NOTICE] switch_ivr_originate.c:553 Ring Ready sofia/internal/beth@stage.illumy1.com! recv 418 bytes from wss/[50.246.121.173]:34738 at 20:27:38.973706: ------------------------------------------------------------------------ SIP/2.0 480 Temporarily Unavailable Via: SIP/2.0/WSS 18.211.78.106:443;rport;branch=z9hG4bKye2ergXZB23jK From: "Beth User" <sip:beth@18.211.78.106>;tag=yHm5UmrgvjmeN To: <sip:r6ucrocm@3val7ifjblg6.invalid;transport=ws;received= 50.246.121.173:34738>;tag=9eibedbcg9 CSeq: 10383836 INVITE Call-ID: 94fe2e19-5e63-1238-2787-0251a831415e Supported: outbound User-Agent: nathan@stage.illumy1.com Content-Length: 0 send 485 bytes to wss/[50.246.121.173]:34738 at 20:27:38.973840: ------------------------------------------------------------------------ ACK sip:r6ucrocm@3val7ifjblg6.invalid;transport=ws;received= 50.246.121.173:34738 SIP/2.0 Via: SIP/2.0/WSS 18.211.78.106:443;rport;branch=z9hG4bKye2ergXZB23jK Route: <sip:r6ucrocm@50.246.121.173:34738>;transport=wss Max-Forwards: 69 From: "Beth User" <sip:beth@18.211.78.106>;tag=yHm5UmrgvjmeN To: <sip:r6ucrocm@3val7ifjblg6.invalid;transport=ws;received= 50.246.121.173:34738>;tag=9eibedbcg9 Call-ID: 94fe2e19-5e63-1238-2787-0251a831415e CSeq: 10383836 ACK Content-Length: 0 2019-09-30 20:27:38.971902 [DEBUG] sofia.c:7289 Channel sofia/internal/r6ucrocm@3val7ifjblg6.invalid entering state [terminated][480] 2019-09-30 20:27:38.971902 [NOTICE] sofia.c:8522 Hangup sofia/internal/r6ucrocm@3val7ifjblg6.invalid [CS_CONSUME_MEDIA] [NO_USER_RESPONSE] 2019-09-30 20:27:38.971902 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/r6ucrocm@3val7ifjblg6.invalid) Running State Change CS_HANGUP (Cur 6 Tot 928) 2019-09-30 20:27:38.971902 [DEBUG] switch_core_state_machine.c:848 (sofia/internal/r6ucrocm@3val7ifjblg6.invalid) Callstate Change RINGING -> HANGUP 2019-09-30 20:27:38.971902 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/r6ucrocm@3val7ifjblg6.invalid) State HANGUP 2019-09-30 20:27:38.971902 [DEBUG] mod_sofia.c:460 Channel sofia/internal/r6ucrocm@3val7ifjblg6.invalid hanging up, cause: NO_USER_RESPONSE 2019-09-30 20:27:38.971902 [DEBUG] switch_core_state_machine.c:60 sofia/internal/r6ucrocm@3val7ifjblg6.invalid Standard HANGUP, cause: NO_USER_RESPONSE 2019-09-30 20:27:38.971902 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/r6ucrocm@3val7ifjblg6.invalid) State HANGUP going to sleep 2019-09-30 20:27:38.971902 [DEBUG] switch_core_state_machine.c:620 (sofia/internal/r6ucrocm@3val7ifjblg6.invalid) State Change CS_HANGUP -> CS_REPORTING 2019-09-30 20:27:38.971902 [DEBUG] switch_core_state_machine.c:585 (sofia/internal/r6ucrocm@3val7ifjblg6.invalid) Running State Change CS_REPORTING (Cur 6 Tot 928) 2019-09-30 20:27:38.971902 [DEBUG] switch_core_state_machine.c:936 (sofia/internal/r6ucrocm@3val7ifjblg6.invalid) State REPORTING 2019-09-30 20:27:38.971902 [DEBUG] mod_odbc_cdr.c:345 sql INSERT INTO cdr_table_both (CallId, TEST_id) VALUES ('56c0cd2d-e19b-4c45-a278-81ed26d09636', 'beth@18.211.78.106') 2019-09-30 20:27:38.971902 [DEBUG] mod_odbc_cdr.c:345 sql INSERT INTO cdr_table_b_leg (TelNumberFull, CallId, orig_id, CallerID, IP, term_id, ClientId) VALUES ('r6ucrocm', '59f602c8-5c38-4c8b-984f-7f09197e9fa3', '56c0cd2d-e19b-4c45-a278-81ed26d09636', 'beth', '50.246.121.173', '94fe2e19-5e63-1238-2787-0251a831415e', '56c0cd2d-e19b-4c45-a278-81ed26d09636') 2019-09-30 20:27:38.971902 [DEBUG] switch_core_state_machine.c:174 sofia/internal/r6ucrocm@3val7ifjblg6.invalid Standard REPORTING, cause: NO_USER_RESPONSE 2019-09-30 20:27:38.971902 [DEBUG] switch_core_state_machine.c:936 (sofia/internal/r6ucrocm@3val7ifjblg6.invalid) State REPORTING going to sleep 2019-09-30 20:27:38.971902 [DEBUG] switch_core_state_machine.c:611 (sofia/internal/r6ucrocm@3val7ifjblg6.invalid) State Change CS_REPORTING -> CS_DESTROY 2019-09-30 20:27:38.971902 [DEBUG] switch_core_session.c:1726 Session 928 (sofia/internal/r6ucrocm@3val7ifjblg6.invalid) Locked, Waiting on external entities --
<> nathan stratton
Nathan --
So this is a know issue? We are using SIP.js on the web side and Libre SIP stack for iOS and Android, both have issues with this bug
I am not sure whether the observed behaviour is an issue per se; FreeSWITCH itself considers the presented endpoint (the UDP one) as legitimate as it definitely listens to requests, it could eventually honour, on the provided host:port combination. This is likely a matter of semantics, but I think the RFC might favour the current behaviour since the Contact endpoint is expected to be global (i.e. function outside of the current dialog). Back to the matter at hand, when terminating call that's ringing, the CANCEL is properly handled by the server when dispatched over the existing websocket connection; I've tested this with a default FS install and a slightly modified version of the sip.js demo here: https://sipjs.com/guides/full-demo-app/ -C
On Tue, Oct 1, 2019 at 4:29 PM Ciprian Dosoftei <ciprian.dosoftei@gmail.com> wrote:
Nathan --
So this is a know issue? We are using SIP.js on the web side and Libre SIP stack for iOS and Android, both have issues with this bug
I am not sure whether the observed behaviour is an issue per se; FreeSWITCH itself considers the presented endpoint (the UDP one) as legitimate as it definitely listens to requests, it could eventually honour, on the provided host:port combination.
It may be a legitimate port (wish it was not), but we only have port 443 SIP over WSS open in the firewall. This is likely a matter of semantics, but I think the RFC might favour the
current behaviour since the Contact endpoint is expected to be global (i.e. function outside of the current dialog).
Not sure how it can be expected behavior to use a SIP UDP 5060 contact over a WSS interface that has no way of talking to SIP UDP 5060. Back to the matter at hand, when terminating call that's ringing, the
CANCEL is properly handled by the server when dispatched over the existing websocket connection; I've tested this with a default FS install and a slightly modified version of the sip.js demo here: https://sipjs.com/guides/full-demo-app/
How did you modify SIP.js? -Nathan
This is likely a matter of semantics, but I think the RFC might favour the
current behaviour since the Contact endpoint is expected to be global (i.e. function outside of the current dialog).
Not sure how it can be expected behavior to use a SIP UDP 5060 contact over a WSS interface that has no way of talking to SIP UDP 5060.
Hence the global scope of the Contact endpoint, I guess especially so in a historical context ... for devices limited to a handful of connectivity options, such as WSS, it _might_ be expected to follow a rport approach. As with some SIP concepts, there's a big gap between original spec/RFC intent and the field implementations. Not really sure where this one stands!
How did you modify SIP.js?
I've only modified the linked demo (https://sipjs.com/guides/full-demo-app/) to see how it behaves with a stock FS install, here's the resulting fiddle: http://jsfiddle.net/o890yfs7/ -- line #3 is the host on which the Sofia profile is listening to requests. I've tested against a Docker instance (using host network mode) as follows: FROM debian:buster RUN apt-get update && apt-get install -y gnupg2 wget lsb-release RUN wget -O - https://files.freeswitch.org/repo/deb/debian-release/fsstretch-archive-keyri... | apt-key add - RUN echo "deb http://files.freeswitch.org/repo/deb/debian-release/ `lsb_release -sc` main" > /etc/apt/sources.list.d/freeswitch.list RUN echo "deb-src http://files.freeswitch.org/repo/deb/debian-release/ `lsb_release -sc` main" >> /etc/apt/sources.list.d/freeswitch.list RUN apt-get update && apt-get install -y freeswitch-meta-all RUN rm -rf /etc/freeswitch/sip_profiles/*ipv6* COPY files / CMD ["freeswitch", "-nonat"] There's an intentional 10 seconds delay in the default dialplan you can use to test the CANCEL behaviour while the other extension is ringing.
participants (3)
-
Ciprian Dosoftei
-
Nathan Stratton
-
Victor C