Please do not post logs into email bodies, people use mobile devices to browse this list.

Please do no report issues on this list, its a discussion list.

We have a Bug tracker specifically for issues.
I forgot completely about this thread because its impossible to mentally remember every one of the email threads in a busy mailing list.  

https://jira.freeswitch.org  This has all you need to attach your data and file a proper report.  Otherwise its pure Chaos.....




On Thu, May 18, 2017 at 12:34 PM, Luke Wahlmeier <lwahlmeier@gmail.com> wrote:
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.

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.

Thanks
Luke

On Fri, May 12, 2017 at 12:03 PM, Luke Wahlmeier <lwahlmeier@gmail.com> wrote:
Here is the debug logs from this happening:

f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [NOTICE] switch_channel.c:1104 New Channel sofia/websocket/nobody@52LX8LP8BBWG6990 [f9a97c98-373b-11e7-9136-499bb33ea37e]
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@52LX8LP8BBWG6990) Running State Change CS_NEW (Cur 1 Tot 1)
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] sofia.c:10028 sofia/websocket/nobody@52LX8LP8BBWG6990 receiving invite from 192.168.56.151:53442 version: 1.9.0 git db24869 2017-05-11 18:22:45Z 64bit
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] sofia.c:11325 Setting NAT mode based on websockets
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] sofia.c:7247 Channel sofia/websocket/nobody@52LX8LP8BBWG6990 entering state [received][100]
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] sofia.c:7257 Remote SDP:
f9a97c98-373b-11e7-9136-499bb33ea37e v=0
f9a97c98-373b-11e7-9136-499bb33ea37e o=- 196478633 2 IN IP4 192.168.56.151
f9a97c98-373b-11e7-9136-499bb33ea37e s=-
f9a97c98-373b-11e7-9136-499bb33ea37e c=IN IP4 192.168.56.151
f9a97c98-373b-11e7-9136-499bb33ea37e t=0 0
f9a97c98-373b-11e7-9136-499bb33ea37e m=audio 42504 RTP/AVP 0 100
f9a97c98-373b-11e7-9136-499bb33ea37e a=rtpmap:0 PCMU/8000
f9a97c98-373b-11e7-9136-499bb33ea37e a=maxptime:20
f9a97c98-373b-11e7-9136-499bb33ea37e
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
f9a97c98-373b-11e7-9136-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
f9a97c98-373b-11e7-9136-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:20:64000:1]
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_media.c:3425 Set Codec sofia/websocket/nobody@52LX8LP8BBWG6990 PCMU/8000 20 ms 160 samples 64000 bits 1 channels
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_codec.c:111 sofia/websocket/nobody@52LX8LP8BBWG6990 Original read codec set to PCMU:0
f9a97c98-373b-11e7-9136-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.
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_media.c:5427 sofia/websocket/nobody@52LX8LP8BBWG6990 Set 2833 dtmf send payload to 101 recv payload to 101
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] sofia.c:7670 (sofia/websocket/nobody@52LX8LP8BBWG6990) State Change CS_NEW -> CS_INIT
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_state_machine.c:603 (sofia/websocket/nobody@52LX8LP8BBWG6990) State NEW
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@52LX8LP8BBWG6990) Running State Change CS_INIT (Cur 1 Tot 1)
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_state_machine.c:627 (sofia/websocket/nobody@52LX8LP8BBWG6990) State INIT
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] mod_sofia.c:93 sofia/websocket/nobody@52LX8LP8BBWG6990 SOFIA INIT
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_state_machine.c:40 sofia/websocket/nobody@52LX8LP8BBWG6990 Standard INIT
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:48 (sofia/websocket/nobody@52LX8LP8BBWG6990) State Change CS_INIT -> CS_ROUTING
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:627 (sofia/websocket/nobody@52LX8LP8BBWG6990) State INIT going to sleep
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@52LX8LP8BBWG6990) Running State Change CS_ROUTING (Cur 1 Tot 1)
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_channel.c:2249 (sofia/websocket/nobody@52LX8LP8BBWG6990) Callstate Change DOWN -> RINGING
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:643 (sofia/websocket/nobody@52LX8LP8BBWG6990) State ROUTING
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] mod_sofia.c:154 sofia/websocket/nobody@52LX8LP8BBWG6990 SOFIA ROUTING
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:236 sofia/websocket/nobody@52LX8LP8BBWG6990 Standard ROUTING
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [INFO] mod_dialplan_xml.c:637 Processing unknown <>->52LX8LP8BBWG6990 in context wss-dialplan
f9a97c98-373b-11e7-9136-499bb33ea37e Dialplan: sofia/websocket/nobody@52LX8LP8BBWG6990 parsing [wss-dialplan->wss-dialplan] continue=false
f9a97c98-373b-11e7-9136-499bb33ea37e Dialplan: sofia/websocket/nobody@52LX8LP8BBWG6990 Regex (PASS) [wss-dialplan] destination_number(52LX8LP8BBWG6990) =~ /.+/ break=on-false
f9a97c98-373b-11e7-9136-499bb33ea37e Dialplan: sofia/websocket/nobody@52LX8LP8BBWG6990 Action conference(test123)
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:286 (sofia/websocket/nobody@52LX8LP8BBWG6990) State Change CS_ROUTING -> CS_EXECUTE
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:643 (sofia/websocket/nobody@52LX8LP8BBWG6990) State ROUTING going to sleep
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@52LX8LP8BBWG6990) Running State Change CS_EXECUTE (Cur 1 Tot 1)
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:650 (sofia/websocket/nobody@52LX8LP8BBWG6990) State EXECUTE
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] mod_sofia.c:209 sofia/websocket/nobody@52LX8LP8BBWG6990 SOFIA EXECUTE
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:328 sofia/websocket/nobody@52LX8LP8BBWG6990 Standard EXECUTE
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_session.c:2707 Application conference Requires media! pre_answering channel sofia/websocket/nobody@52LX8LP8BBWG6990
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [INFO] switch_core_session.c:2709 Sending early media
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_media.c:8144 AUDIO RTP [sofia/websocket/nobody@52LX8LP8BBWG6990] 172.16.19.215 port 27662 -> 192.168.56.151 port 42504 codec: 0 ms: 20
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_rtp.c:4096 Starting timer [soft] 160 bytes per 20ms
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_media.c:8447 sofia/websocket/nobody@52LX8LP8BBWG6990 Set 2833 dtmf send payload to 101
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_media.c:8454 sofia/websocket/nobody@52LX8LP8BBWG6990 Set 2833 dtmf receive payload to 101
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_media.c:8477 sofia/websocket/nobody@52LX8LP8BBWG6990 Set rtp dtmf delay to 40
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] mod_sofia.c:2512 Ring SDP:
f9a97c98-373b-11e7-9136-499bb33ea37e v=0
f9a97c98-373b-11e7-9136-499bb33ea37e o=FreeSWITCH 1494583976 1494583977 IN IP4 172.16.19.215
f9a97c98-373b-11e7-9136-499bb33ea37e s=FreeSWITCH
f9a97c98-373b-11e7-9136-499bb33ea37e c=IN IP4 172.16.19.215
f9a97c98-373b-11e7-9136-499bb33ea37e t=0 0
f9a97c98-373b-11e7-9136-499bb33ea37e m=audio 27662 RTP/AVP 0 101
f9a97c98-373b-11e7-9136-499bb33ea37e a=rtpmap:0 PCMU/8000
f9a97c98-373b-11e7-9136-499bb33ea37e a=rtpmap:101 telephone-event/8000
f9a97c98-373b-11e7-9136-499bb33ea37e a=fmtp:101 0-16
f9a97c98-373b-11e7-9136-499bb33ea37e a=ptime:20
f9a97c98-373b-11e7-9136-499bb33ea37e a=sendrecv
f9a97c98-373b-11e7-9136-499bb33ea37e
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [NOTICE] mod_sofia.c:2515 Pre-Answer sofia/websocket/nobody@52LX8LP8BBWG6990!
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_channel.c:3481 (sofia/websocket/nobody@52LX8LP8BBWG6990) Callstate Change RINGING -> EARLY
f9a97c98-373b-11e7-9136-499bb33ea37e EXECUTE sofia/websocket/nobody@52LX8LP8BBWG6990 conference(test123)
f9a97c98-373b-11e7-9136-499bb33ea37e v=0
f9a97c98-373b-11e7-9136-499bb33ea37e o=FreeSWITCH 1494583976 1494583978 IN IP4 172.16.19.215
f9a97c98-373b-11e7-9136-499bb33ea37e s=FreeSWITCH
f9a97c98-373b-11e7-9136-499bb33ea37e c=IN IP4 172.16.19.215
f9a97c98-373b-11e7-9136-499bb33ea37e t=0 0
f9a97c98-373b-11e7-9136-499bb33ea37e m=audio 27662 RTP/AVP 0 101
f9a97c98-373b-11e7-9136-499bb33ea37e a=rtpmap:0 PCMU/8000
f9a97c98-373b-11e7-9136-499bb33ea37e a=rtpmap:101 telephone-event/8000
f9a97c98-373b-11e7-9136-499bb33ea37e a=fmtp:101 0-16
f9a97c98-373b-11e7-9136-499bb33ea37e a=ptime:20
f9a97c98-373b-11e7-9136-499bb33ea37e a=sendrecv
f9a97c98-373b-11e7-9136-499bb33ea37e
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] sofia.c:7247 Channel sofia/websocket/nobody@52LX8LP8BBWG6990 entering state [early][183]
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [NOTICE] mod_conference.c:1829 Channel [sofia/websocket/nobody@52LX8LP8BBWG6990] has been answered
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_channel.c:3780 (sofia/websocket/nobody@52LX8LP8BBWG6990) Callstate Change EARLY -> ACTIVE
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] sofia.c:7247 Channel sofia/websocket/nobody@52LX8LP8BBWG6990 entering state [completed][200]
2017-05-12 17:53:58.932851 [DEBUG] mod_conference.c:3289 using channel sound prefix: /tmp/fs1.8/share/freeswitch/sounds/en/us/callie
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] conference_member.c:1715 Raw Codec Activation Success L16@8000hz 1 channel 20ms
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] conference_member.c:1762 Raw Codec Activation Success L16@8000hz 1 channel 20ms
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_codec.c:223 sofia/websocket/nobody@52LX8LP8BBWG6990 Push codec L16:100
2017-05-12 17:53:58.932851 [DEBUG] mod_conference.c:227 Setup timer success interval: 20  samples: 160
2017-05-12 17:53:58.932851 [ERR] switch_core_video.c:2868 This function is not available, libpng not installed
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] conference_loop.c:1306 Setup timer soft success interval: 20  samples: 160 from codec PCMU
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [NOTICE] switch_channel.c:1104 New Channel sofia/websocket/nobody@3PXT9NIJPMV6KC8W [02b30be2-373c-11e7-913a-499bb33ea37e]
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Running State Change CS_NEW (Cur 2 Tot 2)
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] sofia.c:10028 sofia/websocket/nobody@3PXT9NIJPMV6KC8W receiving invite from 192.168.56.151:53568 version: 1.9.0 git db24869 2017-05-11 18:22:45Z 64bit
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] sofia.c:11325 Setting NAT mode based on websockets
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] sofia.c:7247 Channel sofia/websocket/nobody@3PXT9NIJPMV6KC8W entering state [received][100]
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] sofia.c:7257 Remote SDP:
02b30be2-373c-11e7-913a-499bb33ea37e v=0
02b30be2-373c-11e7-913a-499bb33ea37e o=- 716582477 2 IN IP4 192.168.56.151
02b30be2-373c-11e7-913a-499bb33ea37e s=-
02b30be2-373c-11e7-913a-499bb33ea37e c=IN IP4 192.168.56.151
02b30be2-373c-11e7-913a-499bb33ea37e t=0 0
02b30be2-373c-11e7-913a-499bb33ea37e m=audio 11866 RTP/AVP 0 100
02b30be2-373c-11e7-913a-499bb33ea37e a=rtpmap:0 PCMU/8000
02b30be2-373c-11e7-913a-499bb33ea37e a=maxptime:20
02b30be2-373c-11e7-913a-499bb33ea37e
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
02b30be2-373c-11e7-913a-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
02b30be2-373c-11e7-913a-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:20:64000:1]
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:3425 Set Codec sofia/websocket/nobody@3PXT9NIJPMV6KC8W PCMU/8000 20 ms 160 samples 64000 bits 1 channels
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_codec.c:111 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Original read codec set to PCMU:0
02b30be2-373c-11e7-913a-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.
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:5427 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Set 2833 dtmf send payload to 101 recv payload to 101
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] sofia.c:7670 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State Change CS_NEW -> CS_INIT
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:603 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State NEW
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Running State Change CS_INIT (Cur 2 Tot 2)
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:627 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State INIT
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] mod_sofia.c:93 sofia/websocket/nobody@3PXT9NIJPMV6KC8W SOFIA INIT
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:40 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Standard INIT
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:48 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State Change CS_INIT -> CS_ROUTING
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:627 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State INIT going to sleep
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Running State Change CS_ROUTING (Cur 2 Tot 2)
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_channel.c:2249 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Callstate Change DOWN -> RINGING
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:643 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State ROUTING
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] mod_sofia.c:154 sofia/websocket/nobody@3PXT9NIJPMV6KC8W SOFIA ROUTING
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:236 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Standard ROUTING
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [INFO] mod_dialplan_xml.c:637 Processing unknown <>->3PXT9NIJPMV6KC8W in context wss-dialplan
02b30be2-373c-11e7-913a-499bb33ea37e Dialplan: sofia/websocket/nobody@3PXT9NIJPMV6KC8W parsing [wss-dialplan->wss-dialplan] continue=false
02b30be2-373c-11e7-913a-499bb33ea37e Dialplan: sofia/websocket/nobody@3PXT9NIJPMV6KC8W Regex (PASS) [wss-dialplan] destination_number(3PXT9NIJPMV6KC8W) =~ /.+/ break=on-false
02b30be2-373c-11e7-913a-499bb33ea37e Dialplan: sofia/websocket/nobody@3PXT9NIJPMV6KC8W Action conference(test123)
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:286 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State Change CS_ROUTING -> CS_EXECUTE
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:643 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State ROUTING going to sleep
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Running State Change CS_EXECUTE (Cur 2 Tot 2)
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:650 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State EXECUTE
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] mod_sofia.c:209 sofia/websocket/nobody@3PXT9NIJPMV6KC8W SOFIA EXECUTE
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:328 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Standard EXECUTE
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_session.c:2707 Application conference Requires media! pre_answering channel sofia/websocket/nobody@3PXT9NIJPMV6KC8W
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [INFO] switch_core_session.c:2709 Sending early media
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:8144 AUDIO RTP [sofia/websocket/nobody@3PXT9NIJPMV6KC8W] 172.16.19.215 port 28858 -> 192.168.56.151 port 11866 codec: 0 ms: 20
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_rtp.c:4096 Starting timer [soft] 160 bytes per 20ms
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:8447 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Set 2833 dtmf send payload to 101
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:8454 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Set 2833 dtmf receive payload to 101
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:8477 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Set rtp dtmf delay to 40
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] mod_sofia.c:2512 Ring SDP:
02b30be2-373c-11e7-913a-499bb33ea37e v=0
02b30be2-373c-11e7-913a-499bb33ea37e o=FreeSWITCH 1494582796 1494582797 IN IP4 172.16.19.215
02b30be2-373c-11e7-913a-499bb33ea37e s=FreeSWITCH
02b30be2-373c-11e7-913a-499bb33ea37e c=IN IP4 172.16.19.215
02b30be2-373c-11e7-913a-499bb33ea37e t=0 0
02b30be2-373c-11e7-913a-499bb33ea37e m=audio 28858 RTP/AVP 0 101
02b30be2-373c-11e7-913a-499bb33ea37e a=rtpmap:0 PCMU/8000
02b30be2-373c-11e7-913a-499bb33ea37e a=rtpmap:101 telephone-event/8000
02b30be2-373c-11e7-913a-499bb33ea37e a=fmtp:101 0-16
02b30be2-373c-11e7-913a-499bb33ea37e a=ptime:20
02b30be2-373c-11e7-913a-499bb33ea37e a=sendrecv
02b30be2-373c-11e7-913a-499bb33ea37e
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [NOTICE] mod_sofia.c:2515 Pre-Answer sofia/websocket/nobody@3PXT9NIJPMV6KC8W!
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_channel.c:3481 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Callstate Change RINGING -> EARLY
02b30be2-373c-11e7-913a-499bb33ea37e EXECUTE sofia/websocket/nobody@3PXT9NIJPMV6KC8W conference(test123)
02b30be2-373c-11e7-913a-499bb33ea37e v=0
02b30be2-373c-11e7-913a-499bb33ea37e o=FreeSWITCH 1494582796 1494582798 IN IP4 172.16.19.215
02b30be2-373c-11e7-913a-499bb33ea37e s=FreeSWITCH
02b30be2-373c-11e7-913a-499bb33ea37e c=IN IP4 172.16.19.215
02b30be2-373c-11e7-913a-499bb33ea37e t=0 0
02b30be2-373c-11e7-913a-499bb33ea37e m=audio 28858 RTP/AVP 0 101
02b30be2-373c-11e7-913a-499bb33ea37e a=rtpmap:0 PCMU/8000
02b30be2-373c-11e7-913a-499bb33ea37e a=rtpmap:101 telephone-event/8000
02b30be2-373c-11e7-913a-499bb33ea37e a=fmtp:101 0-16
02b30be2-373c-11e7-913a-499bb33ea37e a=ptime:20
02b30be2-373c-11e7-913a-499bb33ea37e a=sendrecv
02b30be2-373c-11e7-913a-499bb33ea37e
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] sofia.c:7247 Channel sofia/websocket/nobody@3PXT9NIJPMV6KC8W entering state [early][183]
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [NOTICE] mod_conference.c:1829 Channel [sofia/websocket/nobody@3PXT9NIJPMV6KC8W] has been answered
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_channel.c:3780 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Callstate Change EARLY -> ACTIVE
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] sofia.c:7247 Channel sofia/websocket/nobody@3PXT9NIJPMV6KC8W entering state [completed][200]
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] conference_member.c:1715 Raw Codec Activation Success L16@8000hz 1 channel 20ms
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] conference_member.c:1762 Raw Codec Activation Success L16@8000hz 1 channel 20ms
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_codec.c:223 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Push codec L16:100
2017-05-12 17:54:14.092839 [ERR] switch_core_video.c:2868 This function is not available, libpng not installed
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] conference_loop.c:1306 Setup timer soft success interval: 20  samples: 160 from codec PCMU

This is where session 02b30be2-373c-11e7-913a-499bb33ea37e wss socket gets an ssl errror:
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.952843 [DEBUG] sofia.c:7247 Channel sofia/websocket/nobody@52LX8LP8BBWG6990 entering state [terminating][0]
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.952843 [NOTICE] sofia.c:8438 Hangup sofia/websocket/nobody@52LX8LP8BBWG6990 [CS_EXECUTE] [NORMAL_UNSPECIFIED]
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [INFO] conference_loop.c:1621 Channel leaving conference, cause: NORMAL_UNSPECIFIED
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] mod_conference.c:2404 sofia/websocket/nobody@52LX8LP8BBWG6990 skip receive message [TRANSFER] (channel is hungup already)
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_media.c:11838 sofia/websocket/nobody@52LX8LP8BBWG6990 skip receive message [BITRATE_REQ] (channel is hungup already)
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_codec.c:248 sofia/websocket/nobody@52LX8LP8BBWG6990 Restore previous codec PCMU:0.
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_session.c:2884 sofia/websocket/nobody@52LX8LP8BBWG6990 skip receive message [PHONE_EVENT] (channel is hungup already)
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:650 (sofia/websocket/nobody@52LX8LP8BBWG6990) State EXECUTE going to sleep
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@52LX8LP8BBWG6990) Running State Change CS_HANGUP (Cur 2 Tot 2)
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:850 (sofia/websocket/nobody@52LX8LP8BBWG6990) Callstate Change ACTIVE -> HANGUP
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:852 (sofia/websocket/nobody@52LX8LP8BBWG6990) State HANGUP
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] mod_sofia.c:449 Channel sofia/websocket/nobody@52LX8LP8BBWG6990 hanging up, cause: NORMAL_UNSPECIFIED
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:60 sofia/websocket/nobody@52LX8LP8BBWG6990 Standard HANGUP, cause: NORMAL_UNSPECIFIED
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:852 (sofia/websocket/nobody@52LX8LP8BBWG6990) State HANGUP going to sleep
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:619 (sofia/websocket/nobody@52LX8LP8BBWG6990) State Change CS_HANGUP -> CS_REPORTING
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@52LX8LP8BBWG6990) Running State Change CS_REPORTING (Cur 2 Tot 2)
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:938 (sofia/websocket/nobody@52LX8LP8BBWG6990) State REPORTING
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:174 sofia/websocket/nobody@52LX8LP8BBWG6990 Standard REPORTING, cause: NORMAL_UNSPECIFIED
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:938 (sofia/websocket/nobody@52LX8LP8BBWG6990) State REPORTING going to sleep
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:610 (sofia/websocket/nobody@52LX8LP8BBWG6990) State Change CS_REPORTING -> CS_DESTROY
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_session.c:1712 Session 1 (sofia/websocket/nobody@52LX8LP8BBWG6990) Locked, Waiting on external entities
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [NOTICE] switch_core_session.c:1730 Session 1 (sofia/websocket/nobody@52LX8LP8BBWG6990) Ended
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [NOTICE] switch_core_session.c:1734 Close Channel sofia/websocket/nobody@52LX8LP8BBWG6990 [CS_DESTROY]
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:741 (sofia/websocket/nobody@52LX8LP8BBWG6990) Running State Change CS_DESTROY (Cur 1 Tot 2)
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:751 (sofia/websocket/nobody@52LX8LP8BBWG6990) State DESTROY
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] mod_sofia.c:354 sofia/websocket/nobody@52LX8LP8BBWG6990 SOFIA DESTROY
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:181 sofia/websocket/nobody@52LX8LP8BBWG6990 Standard DESTROY
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:751 (sofia/websocket/nobody@52LX8LP8BBWG6990) State DESTROY going to sleep
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.112842 [DEBUG] sofia.c:7247 Channel sofia/websocket/nobody@3PXT9NIJPMV6KC8W entering state [terminating][0]
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.112842 [NOTICE] sofia.c:8438 Hangup sofia/websocket/nobody@3PXT9NIJPMV6KC8W [CS_EXECUTE] [NORMAL_UNSPECIFIED]
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [INFO] conference_loop.c:1621 Channel leaving conference, cause: NORMAL_UNSPECIFIED
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] mod_conference.c:2404 sofia/websocket/nobody@3PXT9NIJPMV6KC8W skip receive message [TRANSFER] (channel is hungup already)
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_media.c:11838 sofia/websocket/nobody@3PXT9NIJPMV6KC8W skip receive message [BITRATE_REQ] (channel is hungup already)
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_codec.c:248 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Restore previous codec PCMU:0.
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_session.c:2884 sofia/websocket/nobody@3PXT9NIJPMV6KC8W skip receive message [PHONE_EVENT] (channel is hungup already)
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:650 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State EXECUTE going to sleep
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Running State Change CS_HANGUP (Cur 1 Tot 2)
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:850 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Callstate Change ACTIVE -> HANGUP
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:852 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State HANGUP
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] mod_sofia.c:449 Channel sofia/websocket/nobody@3PXT9NIJPMV6KC8W hanging up, cause: NORMAL_UNSPECIFIED
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:60 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Standard HANGUP, cause: NORMAL_UNSPECIFIED
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:852 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State HANGUP going to sleep
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:619 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State Change CS_HANGUP -> CS_REPORTING
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Running State Change CS_REPORTING (Cur 1 Tot 2)
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:938 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State REPORTING
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:174 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Standard REPORTING, cause: NORMAL_UNSPECIFIED
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:938 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State REPORTING going to sleep
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:610 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State Change CS_REPORTING -> CS_DESTROY
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_session.c:1712 Session 2 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Locked, Waiting on external entities
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [NOTICE] switch_core_session.c:1730 Session 2 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Ended
02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [NOTICE] switch_core_session.c:1734 Close Channel sofia/websocket/nobody@3PXT9NIJPMV6KC8W [CS_DESTROY]

On Fri, May 12, 2017 at 11:51 AM, Luke Wahlmeier <lwahlmeier@gmail.com> wrote:
Thanks Michael,

I am more then happy to setup something with libks if needed.

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.

The sessions that is being cleaned up sends the logs messages as its doing it:
2017-05-12 17:32:46.607768 [NOTICE] sofia.c:8438 Hangup sofia/websocket/nobody@1LF3F6I924P9WH6U [CS_EXECUTE] [NORMAL_UNSPECIFIED]
2017-05-12 17:32:46.627768 [INFO] conference_loop.c:1621 Channel leaving conference, cause: NORMAL_UNSPECIFIED
2017-05-12 17:32:46.627768 [NOTICE] switch_core_session.c:1730 Session 46 (sofia/websocket/nobody@1LF3F6I924P9WH6U) Ended
2017-05-12 17:32:46.627768 [NOTICE] switch_core_session.c:1734 Close Channel sofia/websocket/nobody@1LF3F6I924P9WH6U [CS_DESTROY]

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.

The webRTC connection is in chrome with sip.js.

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.


On Fri, May 12, 2017 at 10:20 AM, Michael Jerris <mike@jerris.com> wrote:
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.


On May 12, 2017, at 11:42 AM, Luke Wahlmeier <lwahlmeier@gmail.com> wrote:

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.

Thanks
Luke

On Thu, May 11, 2017 at 5:12 PM, Luke Wahlmeier <lwahlmeier@gmail.com> wrote:
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.

I was able to reproduce it w/o DTLS/Srtp.  here is a much simpler and cleaned up version of the python script.



On Thu, May 11, 2017 at 4:34 PM, Michael Jerris <mike@jerris.com> wrote:
what is “this environment” ?

On May 11, 2017, at 6:31 PM, Luke Wahlmeier <lwahlmeier@gmail.com> wrote:

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.

Thanks
Luke

On Thu, May 11, 2017 at 4:20 PM, Michael Jerris <mike@jerris.com> wrote:
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.

> On May 11, 2017, at 5:48 PM, Luke Wahlmeier <lwahlmeier@gmail.com> wrote:
>
> 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.
>
> 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.
>
> 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.
>
> Here are the errors:
> python:
> SSLError: [SSL: DECRYPTION_FAILED_OR_BAD_RECORD_MAC] decryption failed or bad record mac (_ssl.c:1750)
> c/c++ (stunnel4):
> SSL_read: 1408F119: error:1408F119:SSL routines:SSL3_GET_RECORD:decryption failed or bad record mac
> Java:
> java.lang.IllegalArgumentException: Bad arguments
>     at javax.crypto.Mac.update(Mac.java:509)
>     at sun.security.ssl.MAC.compute(MAC.java:135)
>     at sun.security.ssl.InputRecord.checkMacTags(InputRecord.java:265)
>     at sun.security.ssl.InputRecord.decrypt(InputRecord.java:216)
>     at sun.security.ssl.EngineInputRecord.decrypt(EngineInputRecord.java:177)
>     at sun.security.ssl.SSLEngineImpl.readRecord(SSLEngineImpl.java:974)
>     at sun.security.ssl.SSLEngineImpl.readNetRecord(SSLEngineImpl.java:907)
>     at sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:781)
>     at javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:624)
>
> 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.
>
> 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.
>


_________________________________________________________________________
Professional FreeSWITCH Consulting Services:
consulting@freeswitch.org
http://www.freeswitchsolutions.com

Official FreeSWITCH Sites
http://www.freeswitch.org
http://confluence.freeswitch.org
http://www.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
http://www.freeswitch.org


_________________________________________________________________________
Professional FreeSWITCH Consulting Services:
consulting@freeswitch.org
http://www.freeswitchsolutions.com

Official FreeSWITCH Sites
http://www.freeswitch.org
http://confluence.freeswitch.org
http://www.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
http://www.freeswitch.org


_________________________________________________________________________
Professional FreeSWITCH Consulting Services:
consulting@freeswitch.org
http://www.freeswitchsolutions.com

Official FreeSWITCH Sites
http://www.freeswitch.org
http://confluence.freeswitch.org
http://www.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
http://www.freeswitch.org




_________________________________________________________________________
Professional FreeSWITCH Consulting Services:
consulting@freeswitch.org
http://www.freeswitchsolutions.com

Official FreeSWITCH Sites
http://www.freeswitch.org
http://confluence.freeswitch.org
http://www.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
http://www.freeswitch.org



--
Anthony Minessale II       ♬ @anthmfs  ♬ @FreeSWITCH  ♬

ClueCon Weekly Development Call 
☎ sip:888@conference.freeswitch.org  ☎ +19193869900