[Freeswitch-users] WSS SSL errors "decryption failed or bad record mac" under load
Anthony Minessale
anthony.minessale at gmail.com
Thu May 18 18:08:25 UTC 2017
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 at 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 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:2
>> 0: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:2
>> 0: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.c
>>>>>>> heckMacTags(InputRecord.java:265)
>>>>>>> > at sun.security.ssl.InputRecord.decrypt(InputRecord.java:216)
>>>>>>> > at sun.security.ssl.EngineInputRe
>>>>>>> cord.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 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/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/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
>
--
Anthony Minessale II ♬ @anthmfs ♬ @FreeSWITCH ♬
☞ http://freeswitch.org/ ☞ http://cluecon.com/ ☞
http://twitter.com/FreeSWITCH
☞ irc.freenode.net #freeswitch ☞ *http://freeswitch.org/g+
<http://freeswitch.org/g+>*
ClueCon Weekly Development Call
☎ sip:888 at conference.freeswitch.org ☎ +19193869900
https://www.youtube.com/watch?v=9XXgW34t40s
https://www.youtube.com/watch?v=NLaDpGQuZDA
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20170518/169f606d/attachment-0001.html
More information about the FreeSWITCH-users
mailing list