<div dir="ltr"><div><div>I have been able to verify this is definitely an issue with the sofia wss transport. If I put my own ssl proxy (stunnel) in front and use sofia ws transport the problem goes away.<br><br>I have tried quite a bit of debugging and cant figure out when/how this is happening, my best guess is something around the ssl locking on connection close, but I have not had the time to dig into that yet.<br><br></div>Thanks<br></div>Luke<br></div><div class="gmail_extra"><br><div class="gmail_quote">On Fri, May 12, 2017 at 12:03 PM, Luke Wahlmeier <span dir="ltr"><<a href="mailto:lwahlmeier@gmail.com" target="_blank">lwahlmeier@gmail.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr">Here is the debug logs from this happening:<br><br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.912851 [NOTICE] switch_channel.c:1104 New Channel sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990 [f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e]<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_state_machine.c:<wbr>584 (sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990) Running State Change CS_NEW (Cur 1 Tot 1)<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] sofia.c:10028 sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990 receiving invite from <a href="http://192.168.56.151:53442" target="_blank">192.168.56.151:53442</a> version: 1.9.0 git db24869 2017-05-11 18:22:45Z 64bit<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] sofia.c:11325 Setting NAT mode based on websockets<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] sofia.c:7247 Channel sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990 entering state [received][100]<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] sofia.c:7257 Remote SDP:<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e v=0<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e o=- 196478633 2 IN IP4 192.168.56.151<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e s=-<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e c=IN IP4 192.168.56.151<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e t=0 0<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e m=audio 42504 RTP/AVP 0 100<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e a=rtpmap:0 PCMU/8000<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e a=maxptime:20<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e <br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[<wbr>PCMU:0:8000:20:64000:1]<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_media.c:5165 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [:100:0:20:0:1]/[PCMU:0:8000:<wbr>20:64000:1]<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_media.c:3425 Set Codec sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990 PCMU/8000 20 ms 160 samples 64000 bits 1 channels<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_codec.c:111 sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990 Original read codec set to PCMU:0<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_media.c:5398 No 2833 in SDP. Liberal DTMF mode adding 101 as telephone-event.<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_media.c:5427 sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990 Set 2833 dtmf send payload to 101 recv payload to 101<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] sofia.c:7670 (sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990) State Change CS_NEW -> CS_INIT<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_state_machine.c:<wbr>603 (sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990) State NEW<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_state_machine.c:<wbr>584 (sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990) Running State Change CS_INIT (Cur 1 Tot 1)<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_state_machine.c:<wbr>627 (sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990) State INIT<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] mod_sofia.c:93 sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990 SOFIA INIT<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_state_machine.c:40 sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990 Standard INIT<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:48 (sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990) State Change CS_INIT -> CS_ROUTING<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:<wbr>627 (sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990) State INIT going to sleep<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:<wbr>584 (sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990) Running State Change CS_ROUTING (Cur 1 Tot 1)<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_channel.c:2249 (sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990) Callstate Change DOWN -> RINGING<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:<wbr>643 (sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990) State ROUTING<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] mod_sofia.c:154 sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990 SOFIA ROUTING<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:<wbr>236 sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990 Standard ROUTING<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.932851 [INFO] mod_dialplan_xml.c:637 Processing unknown <>->52LX8LP8BBWG6990 in context wss-dialplan<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e Dialplan: sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990 parsing [wss-dialplan->wss-dialplan] continue=false<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e Dialplan: sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990 Regex (PASS) [wss-dialplan] destination_number(<wbr>52LX8LP8BBWG6990) =~ /.+/ break=on-false<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e Dialplan: sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990 Action conference(test123)<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:<wbr>286 (sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990) State Change CS_ROUTING -> CS_EXECUTE<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:<wbr>643 (sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990) State ROUTING going to sleep<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:<wbr>584 (sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990) Running State Change CS_EXECUTE (Cur 1 Tot 1)<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:<wbr>650 (sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990) State EXECUTE<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] mod_sofia.c:209 sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990 SOFIA EXECUTE<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:<wbr>328 sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990 Standard EXECUTE<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_session.c:2707 Application conference Requires media! pre_answering channel sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.932851 [INFO] switch_core_session.c:2709 Sending early media<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_media.c:8144 AUDIO RTP [sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990] 172.16.19.215 port 27662 -> 192.168.56.151 port 42504 codec: 0 ms: 20<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_rtp.c:4096 Starting timer [soft] 160 bytes per 20ms<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_media.c:8447 sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990 Set 2833 dtmf send payload to 101<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_media.c:8454 sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990 Set 2833 dtmf receive payload to 101<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_media.c:8477 sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990 Set rtp dtmf delay to 40<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] mod_sofia.c:2512 Ring SDP:<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e v=0<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e o=FreeSWITCH 1494583976 1494583977 IN IP4 172.16.19.215<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e s=FreeSWITCH<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e c=IN IP4 172.16.19.215<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e t=0 0<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e m=audio 27662 RTP/AVP 0 101<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e a=rtpmap:0 PCMU/8000<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e a=rtpmap:101 telephone-event/8000<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e a=fmtp:101 0-16<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e a=ptime:20<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e a=sendrecv<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e <br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.932851 [NOTICE] mod_sofia.c:2515 Pre-Answer sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990!<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_channel.c:3481 (sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990) Callstate Change RINGING -> EARLY<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e EXECUTE sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990 conference(test123)<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e v=0<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e o=FreeSWITCH 1494583976 1494583978 IN IP4 172.16.19.215<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e s=FreeSWITCH<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e c=IN IP4 172.16.19.215<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e t=0 0<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e m=audio 27662 RTP/AVP 0 101<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e a=rtpmap:0 PCMU/8000<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e a=rtpmap:101 telephone-event/8000<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e a=fmtp:101 0-16<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e a=ptime:20<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e a=sendrecv<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e <br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] sofia.c:7247 Channel sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990 entering state [early][183]<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.932851 [NOTICE] mod_conference.c:1829 Channel [sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990] has been answered<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_channel.c:3780 (sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990) Callstate Change EARLY -> ACTIVE<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] sofia.c:7247 Channel sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990 entering state [completed][200]<br>2017-05-12 17:53:58.932851 [DEBUG] mod_conference.c:3289 using channel sound prefix: /tmp/fs1.8/share/freeswitch/<wbr>sounds/en/us/callie<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] conference_member.c:1715 Raw Codec Activation Success L16@8000hz 1 channel 20ms<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] conference_member.c:1762 Raw Codec Activation Success L16@8000hz 1 channel 20ms<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_codec.c:223 sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990 Push codec L16:100<br>2017-05-12 17:53:58.932851 [DEBUG] mod_conference.c:227 Setup timer success interval: 20 samples: 160<br>2017-05-12 17:53:58.932851 [ERR] switch_core_video.c:2868 This function is not available, libpng not installed<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] conference_loop.c:1306 Setup timer soft success interval: 20 samples: 160 from codec PCMU<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [NOTICE] switch_channel.c:1104 New Channel sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W [02b30be2-373c-11e7-913a-<wbr>499bb33ea37e]<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:<wbr>584 (sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W) Running State Change CS_NEW (Cur 2 Tot 2)<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] sofia.c:10028 sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W receiving invite from <a href="http://192.168.56.151:53568" target="_blank">192.168.56.151:53568</a> version: 1.9.0 git db24869 2017-05-11 18:22:45Z 64bit<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] sofia.c:11325 Setting NAT mode based on websockets<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] sofia.c:7247 Channel sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W entering state [received][100]<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] sofia.c:7257 Remote SDP:<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e v=0<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e o=- 716582477 2 IN IP4 192.168.56.151<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e s=-<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e c=IN IP4 192.168.56.151<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e t=0 0<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e m=audio 11866 RTP/AVP 0 100<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e a=rtpmap:0 PCMU/8000<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e a=maxptime:20<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e <br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[<wbr>PCMU:0:8000:20:64000:1]<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:5165 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [:100:0:20:0:1]/[PCMU:0:8000:<wbr>20:64000:1]<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:3425 Set Codec sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W PCMU/8000 20 ms 160 samples 64000 bits 1 channels<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_codec.c:111 sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W Original read codec set to PCMU:0<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:5398 No 2833 in SDP. Liberal DTMF mode adding 101 as telephone-event.<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:5427 sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W Set 2833 dtmf send payload to 101 recv payload to 101<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] sofia.c:7670 (sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W) State Change CS_NEW -> CS_INIT<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:<wbr>603 (sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W) State NEW<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:<wbr>584 (sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W) Running State Change CS_INIT (Cur 2 Tot 2)<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:<wbr>627 (sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W) State INIT<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] mod_sofia.c:93 sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W SOFIA INIT<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:40 sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W Standard INIT<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:48 (sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W) State Change CS_INIT -> CS_ROUTING<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:<wbr>627 (sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W) State INIT going to sleep<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:<wbr>584 (sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W) Running State Change CS_ROUTING (Cur 2 Tot 2)<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_channel.c:2249 (sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W) Callstate Change DOWN -> RINGING<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:<wbr>643 (sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W) State ROUTING<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] mod_sofia.c:154 sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W SOFIA ROUTING<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:<wbr>236 sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W Standard ROUTING<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [INFO] mod_dialplan_xml.c:637 Processing unknown <>->3PXT9NIJPMV6KC8W in context wss-dialplan<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e Dialplan: sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W parsing [wss-dialplan->wss-dialplan] continue=false<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e Dialplan: sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W Regex (PASS) [wss-dialplan] destination_number(<wbr>3PXT9NIJPMV6KC8W) =~ /.+/ break=on-false<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e Dialplan: sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W Action conference(test123)<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:<wbr>286 (sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W) State Change CS_ROUTING -> CS_EXECUTE<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:<wbr>643 (sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W) State ROUTING going to sleep<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:<wbr>584 (sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W) Running State Change CS_EXECUTE (Cur 2 Tot 2)<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:<wbr>650 (sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W) State EXECUTE<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] mod_sofia.c:209 sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W SOFIA EXECUTE<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:<wbr>328 sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W Standard EXECUTE<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_session.c:2707 Application conference Requires media! pre_answering channel sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [INFO] switch_core_session.c:2709 Sending early media<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:8144 AUDIO RTP [sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W] 172.16.19.215 port 28858 -> 192.168.56.151 port 11866 codec: 0 ms: 20<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_rtp.c:4096 Starting timer [soft] 160 bytes per 20ms<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:8447 sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W Set 2833 dtmf send payload to 101<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:8454 sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W Set 2833 dtmf receive payload to 101<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:8477 sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W Set rtp dtmf delay to 40<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] mod_sofia.c:2512 Ring SDP:<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e v=0<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e o=FreeSWITCH 1494582796 1494582797 IN IP4 172.16.19.215<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e s=FreeSWITCH<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e c=IN IP4 172.16.19.215<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e t=0 0<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e m=audio 28858 RTP/AVP 0 101<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e a=rtpmap:0 PCMU/8000<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e a=rtpmap:101 telephone-event/8000<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e a=fmtp:101 0-16<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e a=ptime:20<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e a=sendrecv<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e <br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [NOTICE] mod_sofia.c:2515 Pre-Answer sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W!<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_channel.c:3481 (sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W) Callstate Change RINGING -> EARLY<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e EXECUTE sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W conference(test123)<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e v=0<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e o=FreeSWITCH 1494582796 1494582798 IN IP4 172.16.19.215<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e s=FreeSWITCH<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e c=IN IP4 172.16.19.215<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e t=0 0<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e m=audio 28858 RTP/AVP 0 101<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e a=rtpmap:0 PCMU/8000<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e a=rtpmap:101 telephone-event/8000<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e a=fmtp:101 0-16<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e a=ptime:20<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e a=sendrecv<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e <br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] sofia.c:7247 Channel sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W entering state [early][183]<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [NOTICE] mod_conference.c:1829 Channel [sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W] has been answered<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_channel.c:3780 (sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W) Callstate Change EARLY -> ACTIVE<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] sofia.c:7247 Channel sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W entering state [completed][200]<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] conference_member.c:1715 Raw Codec Activation Success L16@8000hz 1 channel 20ms<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] conference_member.c:1762 Raw Codec Activation Success L16@8000hz 1 channel 20ms<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_codec.c:223 sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W Push codec L16:100<br>2017-05-12 17:54:14.092839 [ERR] switch_core_video.c:2868 This function is not available, libpng not installed<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] conference_loop.c:1306 Setup timer soft success interval: 20 samples: 160 from codec PCMU<br><br>This is where session 02b30be2-373c-11e7-913a-<wbr>499bb33ea37e wss socket gets an ssl errror:<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:54:30.952843 [DEBUG] sofia.c:7247 Channel sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990 entering state [terminating][0]<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:54:30.952843 [NOTICE] sofia.c:8438 Hangup sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990 [CS_EXECUTE] [NORMAL_UNSPECIFIED]<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:54:30.972859 [INFO] conference_loop.c:1621 Channel leaving conference, cause: NORMAL_UNSPECIFIED<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] mod_conference.c:2404 sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990 skip receive message [TRANSFER] (channel is hungup already)<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_media.c:11838 sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990 skip receive message [BITRATE_REQ] (channel is hungup already)<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_codec.c:248 sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990 Restore previous codec PCMU:0.<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_session.c:2884 sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990 skip receive message [PHONE_EVENT] (channel is hungup already)<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:<wbr>650 (sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990) State EXECUTE going to sleep<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:<wbr>584 (sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990) Running State Change CS_HANGUP (Cur 2 Tot 2)<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:<wbr>850 (sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990) Callstate Change ACTIVE -> HANGUP<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:<wbr>852 (sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990) State HANGUP<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] mod_sofia.c:449 Channel sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990 hanging up, cause: NORMAL_UNSPECIFIED<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:60 sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990 Standard HANGUP, cause: NORMAL_UNSPECIFIED<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:<wbr>852 (sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990) State HANGUP going to sleep<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:<wbr>619 (sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990) State Change CS_HANGUP -> CS_REPORTING<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:<wbr>584 (sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990) Running State Change CS_REPORTING (Cur 2 Tot 2)<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:<wbr>938 (sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990) State REPORTING<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:<wbr>174 sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990 Standard REPORTING, cause: NORMAL_UNSPECIFIED<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:<wbr>938 (sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990) State REPORTING going to sleep<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:<wbr>610 (sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990) State Change CS_REPORTING -> CS_DESTROY<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_session.c:1712 Session 1 (sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990) Locked, Waiting on external entities<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:54:30.972859 [NOTICE] switch_core_session.c:1730 Session 1 (sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990) Ended<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:54:30.972859 [NOTICE] switch_core_session.c:1734 Close Channel sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990 [CS_DESTROY]<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:<wbr>741 (sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990) Running State Change CS_DESTROY (Cur 1 Tot 2)<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:<wbr>751 (sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990) State DESTROY<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] mod_sofia.c:354 sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990 SOFIA DESTROY<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:<wbr>181 sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990 Standard DESTROY<br>f9a97c98-373b-11e7-9136-<wbr>499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:<wbr>751 (sofia/websocket/nobody@<wbr>52LX8LP8BBWG6990) State DESTROY going to sleep<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:46.112842 [DEBUG] sofia.c:7247 Channel sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W entering state [terminating][0]<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:46.112842 [NOTICE] sofia.c:8438 Hangup sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W [CS_EXECUTE] [NORMAL_UNSPECIFIED]<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:46.132852 [INFO] conference_loop.c:1621 Channel leaving conference, cause: NORMAL_UNSPECIFIED<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] mod_conference.c:2404 sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W skip receive message [TRANSFER] (channel is hungup already)<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_media.c:11838 sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W skip receive message [BITRATE_REQ] (channel is hungup already)<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_codec.c:248 sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W Restore previous codec PCMU:0.<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_session.c:2884 sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W skip receive message [PHONE_EVENT] (channel is hungup already)<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:<wbr>650 (sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W) State EXECUTE going to sleep<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:<wbr>584 (sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W) Running State Change CS_HANGUP (Cur 1 Tot 2)<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:<wbr>850 (sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W) Callstate Change ACTIVE -> HANGUP<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:<wbr>852 (sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W) State HANGUP<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] mod_sofia.c:449 Channel sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W hanging up, cause: NORMAL_UNSPECIFIED<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:60 sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W Standard HANGUP, cause: NORMAL_UNSPECIFIED<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:<wbr>852 (sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W) State HANGUP going to sleep<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:<wbr>619 (sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W) State Change CS_HANGUP -> CS_REPORTING<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:<wbr>584 (sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W) Running State Change CS_REPORTING (Cur 1 Tot 2)<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:<wbr>938 (sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W) State REPORTING<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:<wbr>174 sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W Standard REPORTING, cause: NORMAL_UNSPECIFIED<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:<wbr>938 (sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W) State REPORTING going to sleep<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:<wbr>610 (sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W) State Change CS_REPORTING -> CS_DESTROY<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_session.c:1712 Session 2 (sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W) Locked, Waiting on external entities<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:46.132852 [NOTICE] switch_core_session.c:1730 Session 2 (sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W) Ended<br>02b30be2-373c-11e7-913a-<wbr>499bb33ea37e 2017-05-12 17:54:46.132852 [NOTICE] switch_core_session.c:1734 Close Channel sofia/websocket/nobody@<wbr>3PXT9NIJPMV6KC8W [CS_DESTROY]<br></div><div class="HOEnZb"><div class="h5"><div class="gmail_extra"><br><div class="gmail_quote">On Fri, May 12, 2017 at 11:51 AM, Luke Wahlmeier <span dir="ltr"><<a href="mailto:lwahlmeier@gmail.com" target="_blank">lwahlmeier@gmail.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr"><div>Thanks Michael,<br><br></div><div>I am more then happy to setup something with libks if needed.<br></div><div><br>I have figured out some more however. It appears that this only happens when a wss connections session has not fully established and is cleaning up because of timing out. The problem is that it causes another wss connection it to get this ssl error, even if that other wss connection has a fully established and running audio session. It is important to note it does not seem to interrupt audio just the wss sip channel, which I am fairly sure can be reestablished for that audio session w/o an issue.<br><br></div><div>The sessions that is being cleaned up sends the logs messages as its doing it:<br>2017-05-12 17:32:46.607768 [NOTICE] sofia.c:8438 Hangup sofia/websocket/nobody@1LF3F6I<wbr>924P9WH6U [CS_EXECUTE] [NORMAL_UNSPECIFIED]<br>2017-05-12 17:32:46.627768 [INFO] conference_loop.c:1621 Channel leaving conference, cause: NORMAL_UNSPECIFIED<br>2017-05-12 17:32:46.627768 [NOTICE] switch_core_session.c:1730 Session 46 (sofia/websocket/nobody@1LF3F6<wbr>I924P9WH6U) Ended<br>2017-05-12 17:32:46.627768 [NOTICE] switch_core_session.c:1734 Close Channel sofia/websocket/nobody@1LF3F6I<wbr>924P9WH6U [CS_DESTROY]<br><br></div><div>I have attached the updated python script, it can duplicate this every time now with only 2 connections. I verified with a webRTC client that if I initiate this first connection in the script, let it close, then connect the webRTC client and get full audio, once the first session from the script times out it causes the webRTC wss connection to get an error and close.<br><br></div><div>The webRTC connection is in chrome with sip.js.<br><br></div><div>Sorry the python script is so nasty, was working through any possible duplicated sip session stuff in it to make sure that was not why it was hitting the second connection.<br></div><div><br></div></div><div class="m_-3021738041502690908HOEnZb"><div class="m_-3021738041502690908h5"><div class="gmail_extra"><br><div class="gmail_quote">On Fri, May 12, 2017 at 10:20 AM, Michael Jerris <span dir="ltr"><<a href="mailto:mike@jerris.com" target="_blank">mike@jerris.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div style="word-wrap:break-word">test on master.. work a similar test for verto maybe, this might have to do with sip specifically trying to keep state. Might make sense to build something out of libks as it has basically the same web socket code, and has both client and server web socket support in it, to do a “real” test”, instead of this fake sip without any state over web sockets.<div><div class="m_-3021738041502690908m_7827931663374584772h5"><div><br><div><br><div><blockquote type="cite"><div>On May 12, 2017, at 11:42 AM, Luke Wahlmeier <<a href="mailto:lwahlmeier@gmail.com" target="_blank">lwahlmeier@gmail.com</a>> wrote:</div><br class="m_-3021738041502690908m_7827931663374584772m_-30872036386906528Apple-interchange-newline"><div><div dir="ltr"><div><div>Just got done testing this on v1.6 head and master, both seem to still have this issue. This box is using libssl version 1.0.1t-1+deb8u6. I am gonna start digging more into the ws/wss/sofia code to see if I can figure it out. Any suggestions on debugging this would be appreciated.<br><br></div>Thanks<br></div>Luke<br></div><div class="gmail_extra"><br><div class="gmail_quote">On Thu, May 11, 2017 at 5:12 PM, Luke Wahlmeier <span dir="ltr"><<a href="mailto:lwahlmeier@gmail.com" target="_blank">lwahlmeier@gmail.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr"><div>Its just in our isolated lab, pretty normal dell xeon server running Jessie 8.6. I just want to get it building on the same box I am testing with so setting that all up.<br><br></div>I was able to reproduce it w/o DTLS/Srtp. here is a much simpler and cleaned up version of the python script.<br><br><br></div><div class="gmail_extra"><br><div class="gmail_quote"><div><div class="m_-3021738041502690908m_7827931663374584772m_-30872036386906528h5">On Thu, May 11, 2017 at 4:34 PM, Michael Jerris <span dir="ltr"><<a href="mailto:mike@jerris.com" target="_blank">mike@jerris.com</a>></span> wrote:<br></div></div><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div><div class="m_-3021738041502690908m_7827931663374584772m_-30872036386906528h5"><div style="word-wrap:break-word">what is “this environment” ?<div><div class="m_-3021738041502690908m_7827931663374584772m_-30872036386906528m_2675276587231758968h5"><div><br><div><blockquote type="cite"><div>On May 11, 2017, at 6:31 PM, Luke Wahlmeier <<a href="mailto:lwahlmeier@gmail.com" target="_blank">lwahlmeier@gmail.com</a>> wrote:</div><br class="m_-3021738041502690908m_7827931663374584772m_-30872036386906528m_2675276587231758968m_-9144194180052449967Apple-interchange-newline"><div><div dir="ltr"><div><div>Yeah I can usually get it to happen within about 5 minutes or so of testing. Still getting all setup to build freeswitch in this environment, but I should have it working by tomorrow. I will try more w/o dtls/srtp as well and make sure it does not need to be on.<br><br></div>Thanks<br></div>Luke<br></div><div class="gmail_extra"><br><div class="gmail_quote">On Thu, May 11, 2017 at 4:20 PM, Michael Jerris <span dir="ltr"><<a href="mailto:mike@jerris.com" target="_blank">mike@jerris.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">if you can reproduce this reliably, i’d try master as well. Unless this is a bug in openssl, i can’t imagine how dtls would come into play in something like this.<br>
<span><br>
> On May 11, 2017, at 5:48 PM, Luke Wahlmeier <<a href="mailto:lwahlmeier@gmail.com" target="_blank">lwahlmeier@gmail.com</a>> wrote:<br>
><br>
> I keep semi-regularly running into issues using the wss transport when using dtls/strp/ice. This is on the latest 1.6.17~34~0fc0946 on Debian jessie, but I am pretty sure it was happening on the last couple releases as well.<br>
><br>
> It seems like something bad/wrong happens to the encrypted data going over the websocket coming from freeswitch when more then 1 websocket connection are going and so far ice/srtp/dtls also seem to be needed in the invite to duplicate it.<br>
><br>
> I have tried many different languages and network/ssl stacks and keep running into this. It is always on data coming in from freeswitch on the websocket connection, and its very very random. Sometimes I will get it 20 times in a row, other times it takes thousands of connections/sessions before it happen. It also, obviously, completely goes away if I use plain ws instead wss.<br>
><br>
> Here are the errors:<br>
> python:<br>
> SSLError: [SSL: DECRYPTION_FAILED_OR_BAD_RECOR<wbr>D_MAC] decryption failed or bad record mac (_ssl.c:1750)<br>
> c/c++ (stunnel4):<br>
> SSL_read: 1408F119: error:1408F119:SSL routines:SSL3_GET_RECORD:decry<wbr>ption failed or bad record mac<br>
> Java:<br>
> java.lang.IllegalArgumentExcep<wbr>tion: Bad arguments<br>
> at javax.crypto.Mac.update(Mac.ja<wbr>va:509)<br>
> at sun.security.ssl.MAC.compute(M<wbr>AC.java:135)<br>
> at sun.security.ssl.InputRecord.c<wbr>heckMacTags(InputRecord.java:2<wbr>65)<br>
> at sun.security.ssl.InputRecord.d<wbr>ecrypt(InputRecord.java:216)<br>
> at sun.security.ssl.EngineInputRe<wbr>cord.decrypt(EngineInputRecord<wbr>.java:177)<br>
> at sun.security.ssl.SSLEngineImpl<wbr>.readRecord(SSLEngineImpl.java<wbr>:974)<br>
> at sun.security.ssl.SSLEngineImpl<wbr>.readNetRecord(SSLEngineImpl.j<wbr>ava:907)<br>
> at sun.security.ssl.SSLEngineImpl<wbr>.unwrap(SSLEngineImpl.java:781<wbr>)<br>
> at javax.net.ssl.SSLEngine.unwrap<wbr>(SSLEngine.java:624)<br>
><br>
> Attached are a simple python script to do the load, my dialplan and sip_profile. The python script can take a few runs before it see the error, and I know its not completing the sip or rtp, but even if it does this still happens.<br>
><br>
> I have also looked at libsofia-sip-ua/tport/ws.c and I dont see anything obvious. I am getting setup to build v1.6 head and test this any guidance on ways I can trouble shoot this better or requests for more info are very welcome.<br>
><br></span></blockquote></div></div></div></blockquote></div><br></div></div></div></div><br></div></div><span>______________________________<wbr>______________________________<wbr>_____________<br>
Professional FreeSWITCH Consulting Services:<br>
<a href="mailto:consulting@freeswitch.org" target="_blank">consulting@freeswitch.org</a><br>
<a href="http://www.freeswitchsolutions.com/" rel="noreferrer" target="_blank">http://www.freeswitchsolutions<wbr>.com</a><br>
<br>
Official FreeSWITCH Sites<br>
<a href="http://www.freeswitch.org/" rel="noreferrer" target="_blank">http://www.freeswitch.org</a><br>
<a href="http://confluence.freeswitch.org/" rel="noreferrer" target="_blank">http://confluence.freeswitch.o<wbr>rg</a><br>
<a href="http://www.cluecon.com/" rel="noreferrer" target="_blank">http://www.cluecon.com</a><br>
<br>
FreeSWITCH-users mailing list<br>
<a href="mailto:FreeSWITCH-users@lists.freeswitch.org" target="_blank">FreeSWITCH-users@lists.freeswi<wbr>tch.org</a><br>
<a href="http://lists.freeswitch.org/mailman/listinfo/freeswitch-users" rel="noreferrer" target="_blank">http://lists.freeswitch.org/ma<wbr>ilman/listinfo/freeswitch-user<wbr>s</a><br>
UNSUBSCRIBE:<a href="http://lists.freeswitch.org/mailman/options/freeswitch-users" rel="noreferrer" target="_blank">http://lists.frees<wbr>witch.org/mailman/options/free<wbr>switch-users</a><br>
<a href="http://www.freeswitch.org/" rel="noreferrer" target="_blank">http://www.freeswitch.org</a><br></span></blockquote></div><br></div>
</blockquote></div><br></div>
______________________________<wbr>______________________________<wbr>_____________<br>Professional FreeSWITCH Consulting Services: <br><a href="mailto:consulting@freeswitch.org" target="_blank">consulting@freeswitch.org</a><br><a href="http://www.freeswitchsolutions.com" target="_blank">http://www.freeswitchsolutions<wbr>.com</a><br><br>Official FreeSWITCH Sites<br><a href="http://www.freeswitch.org" target="_blank">http://www.freeswitch.org</a><br><a href="http://confluence.freeswitch.org" target="_blank">http://confluence.freeswitch.o<wbr>rg</a><br><a href="http://www.cluecon.com" target="_blank">http://www.cluecon.com</a><br><br>FreeSWITCH-users mailing list<br><a href="mailto:FreeSWITCH-users@lists.freeswitch.org" target="_blank">FreeSWITCH-users@lists.freeswi<wbr>tch.org</a><br><a href="http://lists.freeswitch.org/mailman/listinfo/freeswitch-users" target="_blank">http://lists.freeswitch.org/ma<wbr>ilman/listinfo/freeswitch-user<wbr>s</a><br>UNSUBSCRIBE:<a href="http://lists.freeswitch.org/mailman/options/freeswitch-users" target="_blank">http://lists.frees<wbr>witch.org/mailman/options/free<wbr>switch-users</a><br><a href="http://www.freeswitch.org" target="_blank">http://www.freeswitch.org</a></div></blockquote></div><br></div></div></div></div></div><br>______________________________<wbr>______________________________<wbr>_____________<br>
Professional FreeSWITCH Consulting Services:<br>
<a href="mailto:consulting@freeswitch.org" target="_blank">consulting@freeswitch.org</a><br>
<a href="http://www.freeswitchsolutions.com" rel="noreferrer" target="_blank">http://www.freeswitchsolutions<wbr>.com</a><br>
<br>
Official FreeSWITCH Sites<br>
<a href="http://www.freeswitch.org" rel="noreferrer" target="_blank">http://www.freeswitch.org</a><br>
<a href="http://confluence.freeswitch.org" rel="noreferrer" target="_blank">http://confluence.freeswitch.o<wbr>rg</a><br>
<a href="http://www.cluecon.com" rel="noreferrer" target="_blank">http://www.cluecon.com</a><br>
<br>
FreeSWITCH-users mailing list<br>
<a href="mailto:FreeSWITCH-users@lists.freeswitch.org" target="_blank">FreeSWITCH-users@lists.freeswi<wbr>tch.org</a><br>
<a href="http://lists.freeswitch.org/mailman/listinfo/freeswitch-users" rel="noreferrer" target="_blank">http://lists.freeswitch.org/ma<wbr>ilman/listinfo/freeswitch-user<wbr>s</a><br>
UNSUBSCRIBE:<a href="http://lists.freeswitch.org/mailman/options/freeswitch-users" rel="noreferrer" target="_blank">http://lists.frees<wbr>witch.org/mailman/options/free<wbr>switch-users</a><br>
<a href="http://www.freeswitch.org" rel="noreferrer" target="_blank">http://www.freeswitch.org</a><br></blockquote></div><br></div>
</div></div></blockquote></div><br></div>
</div></div></blockquote></div><br></div>