[Freeswitch-users] WSS SSL errors "decryption failed or bad record mac" under load
Luke Wahlmeier
lwahlmeier at gmail.com
Thu May 18 20:43:33 UTC 2017
Will do, thanks
On Thu, May 18, 2017 at 12:08 PM, Anthony Minessale <
anthony.minessale at gmail.com> wrote:
> 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 52LX8LP
>>> 8BBWG6990!
>>> 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 3PXT9NI
>>> JPMV6KC8W!
>>> 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 <(919)%20386-9900>
>
> https://www.youtube.com/watch?v=9XXgW34t40s
> https://www.youtube.com/watch?v=NLaDpGQuZDA
>
> _________________________________________________________________________
> 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/53825c63/attachment-0001.html
More information about the FreeSWITCH-users
mailing list