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

Luke Wahlmeier lwahlmeier at gmail.com
Fri May 12 18:03:07 UTC 2017


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/20170512/5d2ff5dc/attachment-0001.html 


More information about the FreeSWITCH-users mailing list