[Freeswitch-users] WSS SSL errors "decryption failed or bad record mac" under load

Thu May 18 17:34:52 UTC 2017

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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 52LX8LP8BBWG6990)
> State INIT
> f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG]
> mod_sofia.c:93 sofia/websocket/nobody at 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 at 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 at 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 at 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 at 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 at 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 at 52LX8LP8BBWG6990)
> State ROUTING
> f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG]
> mod_sofia.c:154 sofia/websocket/nobody at 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 at 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 at 52LX8LP8BBWG6990
> parsing [wss-dialplan->wss-dialplan] continue=false
> f9a97c98-373b-11e7-9136-499bb33ea37e Dialplan: sofia/websocket/nobody at 52LX8LP8BBWG6990
> Regex (PASS) [wss-dialplan] destination_number(52LX8LP8BBWG6990) =~ /.+/
> break=on-false
> f9a97c98-373b-11e7-9136-499bb33ea37e Dialplan: sofia/websocket/nobody at 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 at 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 at 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 at 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 at 52LX8LP8BBWG6990)
> State EXECUTE
> f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG]
> mod_sofia.c:209 sofia/websocket/nobody at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 52LX8LP8BBWG6990!
> f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG]
> switch_channel.c:3481 (sofia/websocket/nobody at 52LX8LP8BBWG6990) Callstate
> Change RINGING -> EARLY
> f9a97c98-373b-11e7-9136-499bb33ea37e EXECUTE sofia/websocket/nobody at 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 at 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 at 52LX8LP8BBWG6990]
> has been answered
> f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG]
> switch_channel.c:3780 (sofia/websocket/nobody at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 3PXT9NIJPMV6KC8W)
> State INIT
> 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG]
> mod_sofia.c:93 sofia/websocket/nobody at 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 at 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 at 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 at 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 at 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 at 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 at 3PXT9NIJPMV6KC8W)
> State ROUTING
> 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG]
> mod_sofia.c:154 sofia/websocket/nobody at 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 at 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 at 3PXT9NIJPMV6KC8W
> parsing [wss-dialplan->wss-dialplan] continue=false
> 02b30be2-373c-11e7-913a-499bb33ea37e Dialplan: sofia/websocket/nobody at 3PXT9NIJPMV6KC8W
> Regex (PASS) [wss-dialplan] destination_number(3PXT9NIJPMV6KC8W) =~ /.+/
> break=on-false
> 02b30be2-373c-11e7-913a-499bb33ea37e Dialplan: sofia/websocket/nobody at 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 at 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 at 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 at 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 at 3PXT9NIJPMV6KC8W)
> State EXECUTE
> 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG]
> mod_sofia.c:209 sofia/websocket/nobody at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 3PXT9NIJPMV6KC8W!
> 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG]
> switch_channel.c:3481 (sofia/websocket/nobody at 3PXT9NIJPMV6KC8W) Callstate
> Change RINGING -> EARLY
> 02b30be2-373c-11e7-913a-499bb33ea37e EXECUTE sofia/websocket/nobody at 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 at 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 at 3PXT9NIJPMV6KC8W]
> has been answered
> 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG]
> switch_channel.c:3780 (sofia/websocket/nobody at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 52LX8LP8BBWG6990)
> State HANGUP
> f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG]
> mod_sofia.c:449 Channel sofia/websocket/nobody at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 52LX8LP8BBWG6990)
> State DESTROY
> f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG]
> mod_sofia.c:354 sofia/websocket/nobody at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 3PXT9NIJPMV6KC8W)
> State HANGUP
> 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG]
> mod_sofia.c:449 Channel sofia/websocket/nobody at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 3PXT9NIJPMV6KC8W
> [CS_DESTROY]
>
> On Fri, May 12, 2017 at 11:51 AM, Luke Wahlmeier <lwahlmeier at 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 at 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 at 1LF3F6I924P9WH6U) Ended
>> 2017-05-12 17:32:46.627768 [NOTICE] switch_core_session.c:1734 Close
>> Channel sofia/websocket/nobody at 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 at 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 at 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 at 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 at jerris.com>
>>>> wrote:
>>>>
>>>>> what is “this environment” ?
>>>>>
>>>>> On May 11, 2017, at 6:31 PM, Luke Wahlmeier <lwahlmeier at 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 at 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 at 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:2
>>>>>> 65)
>>>>>> >     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.j
>>>>>> ava: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 at 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 at lists.freeswitch.org
>>>>> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
>>>>> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/free
>>>>> switch-users
>>>>> http://www.freeswitch.org
>>>>>
>>>>
>>>>
>>> ____________________________________________________________
>>> _____________
>>> Professional FreeSWITCH Consulting Services:
>>> consulting at 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 at 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 at 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 at lists.freeswitch.org
>>> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
>>> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
>>> http://www.freeswitch.org
>>>
>>
>>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20170518/346b254a/attachment-0001.html 