WSS SSL errors "decryption failed or bad record mac" under load
I keep semi-regularly running into issues using the wss transport when using dtls/strp/ice. This is on the latest 1.6.17~34~0fc0946 on Debian jessie, but I am pretty sure it was happening on the last couple releases as well. It seems like something bad/wrong happens to the encrypted data going over the websocket coming from freeswitch when more then 1 websocket connection are going and so far ice/srtp/dtls also seem to be needed in the invite to duplicate it. I have tried many different languages and network/ssl stacks and keep running into this. It is always on data coming in from freeswitch on the websocket connection, and its very very random. Sometimes I will get it 20 times in a row, other times it takes thousands of connections/sessions before it happen. It also, obviously, completely goes away if I use plain ws instead wss. Here are the errors: python: SSLError: [SSL: DECRYPTION_FAILED_OR_BAD_RECORD_MAC] decryption failed or bad record mac (_ssl.c:1750) c/c++ (stunnel4): SSL_read: 1408F119: error:1408F119:SSL routines:SSL3_GET_RECORD:decryption failed or bad record mac Java: java.lang.IllegalArgumentException: Bad arguments at javax.crypto.Mac.update(Mac.java:509) at sun.security.ssl.MAC.compute(MAC.java:135) at sun.security.ssl.InputRecord.checkMacTags(InputRecord.java:265) at sun.security.ssl.InputRecord.decrypt(InputRecord.java:216) at sun.security.ssl.EngineInputRecord.decrypt(EngineInputRecord.java:177) at sun.security.ssl.SSLEngineImpl.readRecord(SSLEngineImpl.java:974) at sun.security.ssl.SSLEngineImpl.readNetRecord(SSLEngineImpl.java:907) at sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:781) at javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:624) Attached are a simple python script to do the load, my dialplan and sip_profile. The python script can take a few runs before it see the error, and I know its not completing the sip or rtp, but even if it does this still happens. I have also looked at libsofia-sip-ua/tport/ws.c and I dont see anything obvious. I am getting setup to build v1.6 head and test this any guidance on ways I can trouble shoot this better or requests for more info are very welcome. Thanks Luke
if you can reproduce this reliably, i’d try master as well. Unless this is a bug in openssl, i can’t imagine how dtls would come into play in something like this.
On May 11, 2017, at 5:48 PM, Luke Wahlmeier <lwahlmeier@gmail.com> wrote:
I keep semi-regularly running into issues using the wss transport when using dtls/strp/ice. This is on the latest 1.6.17~34~0fc0946 on Debian jessie, but I am pretty sure it was happening on the last couple releases as well.
It seems like something bad/wrong happens to the encrypted data going over the websocket coming from freeswitch when more then 1 websocket connection are going and so far ice/srtp/dtls also seem to be needed in the invite to duplicate it.
I have tried many different languages and network/ssl stacks and keep running into this. It is always on data coming in from freeswitch on the websocket connection, and its very very random. Sometimes I will get it 20 times in a row, other times it takes thousands of connections/sessions before it happen. It also, obviously, completely goes away if I use plain ws instead wss.
Here are the errors: python: SSLError: [SSL: DECRYPTION_FAILED_OR_BAD_RECORD_MAC] decryption failed or bad record mac (_ssl.c:1750) c/c++ (stunnel4): SSL_read: 1408F119: error:1408F119:SSL routines:SSL3_GET_RECORD:decryption failed or bad record mac Java: java.lang.IllegalArgumentException: Bad arguments at javax.crypto.Mac.update(Mac.java:509) at sun.security.ssl.MAC.compute(MAC.java:135) at sun.security.ssl.InputRecord.checkMacTags(InputRecord.java:265) at sun.security.ssl.InputRecord.decrypt(InputRecord.java:216) at sun.security.ssl.EngineInputRecord.decrypt(EngineInputRecord.java:177) at sun.security.ssl.SSLEngineImpl.readRecord(SSLEngineImpl.java:974) at sun.security.ssl.SSLEngineImpl.readNetRecord(SSLEngineImpl.java:907) at sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:781) at javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:624)
Attached are a simple python script to do the load, my dialplan and sip_profile. The python script can take a few runs before it see the error, and I know its not completing the sip or rtp, but even if it does this still happens.
I have also looked at libsofia-sip-ua/tport/ws.c and I dont see anything obvious. I am getting setup to build v1.6 head and test this any guidance on ways I can trouble shoot this better or requests for more info are very welcome.
Yeah I can usually get it to happen within about 5 minutes or so of testing. Still getting all setup to build freeswitch in this environment, but I should have it working by tomorrow. I will try more w/o dtls/srtp as well and make sure it does not need to be on. Thanks Luke On Thu, May 11, 2017 at 4:20 PM, Michael Jerris <mike@jerris.com> wrote:
if you can reproduce this reliably, i’d try master as well. Unless this is a bug in openssl, i can’t imagine how dtls would come into play in something like this.
On May 11, 2017, at 5:48 PM, Luke Wahlmeier <lwahlmeier@gmail.com> wrote:
I keep semi-regularly running into issues using the wss transport when using dtls/strp/ice. This is on the latest 1.6.17~34~0fc0946 on Debian jessie, but I am pretty sure it was happening on the last couple releases as well.
It seems like something bad/wrong happens to the encrypted data going over the websocket coming from freeswitch when more then 1 websocket connection are going and so far ice/srtp/dtls also seem to be needed in the invite to duplicate it.
I have tried many different languages and network/ssl stacks and keep running into this. It is always on data coming in from freeswitch on the websocket connection, and its very very random. Sometimes I will get it 20 times in a row, other times it takes thousands of connections/sessions before it happen. It also, obviously, completely goes away if I use plain ws instead wss.
Here are the errors: python: SSLError: [SSL: DECRYPTION_FAILED_OR_BAD_RECORD_MAC] decryption failed or bad record mac (_ssl.c:1750) c/c++ (stunnel4): SSL_read: 1408F119: error:1408F119:SSL routines:SSL3_GET_RECORD:decryption failed or bad record mac Java: java.lang.IllegalArgumentException: Bad arguments at javax.crypto.Mac.update(Mac.java:509) at sun.security.ssl.MAC.compute(MAC.java:135) at sun.security.ssl.InputRecord.checkMacTags(InputRecord.java:265) at sun.security.ssl.InputRecord.decrypt(InputRecord.java:216) at sun.security.ssl.EngineInputRecord.decrypt( EngineInputRecord.java:177) at sun.security.ssl.SSLEngineImpl.readRecord(SSLEngineImpl.java:974) at sun.security.ssl.SSLEngineImpl.readNetRecord( SSLEngineImpl.java:907) at sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:781) at javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:624)
Attached are a simple python script to do the load, my dialplan and sip_profile. The python script can take a few runs before it see the error, and I know its not completing the sip or rtp, but even if it does this still happens.
I have also looked at libsofia-sip-ua/tport/ws.c and I dont see anything obvious. I am getting setup to build v1.6 head and test this any guidance on ways I can trouble shoot this better or requests for more info are very welcome.
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
Official FreeSWITCH Sites http://www.freeswitch.org http://confluence.freeswitch.org http://www.cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
what is “this environment” ?
On May 11, 2017, at 6:31 PM, Luke Wahlmeier <lwahlmeier@gmail.com> wrote:
Yeah I can usually get it to happen within about 5 minutes or so of testing. Still getting all setup to build freeswitch in this environment, but I should have it working by tomorrow. I will try more w/o dtls/srtp as well and make sure it does not need to be on.
Thanks Luke
On Thu, May 11, 2017 at 4:20 PM, Michael Jerris <mike@jerris.com <mailto:mike@jerris.com>> wrote: if you can reproduce this reliably, i’d try master as well. Unless this is a bug in openssl, i can’t imagine how dtls would come into play in something like this.
On May 11, 2017, at 5:48 PM, Luke Wahlmeier <lwahlmeier@gmail.com <mailto:lwahlmeier@gmail.com>> wrote:
I keep semi-regularly running into issues using the wss transport when using dtls/strp/ice. This is on the latest 1.6.17~34~0fc0946 on Debian jessie, but I am pretty sure it was happening on the last couple releases as well.
It seems like something bad/wrong happens to the encrypted data going over the websocket coming from freeswitch when more then 1 websocket connection are going and so far ice/srtp/dtls also seem to be needed in the invite to duplicate it.
I have tried many different languages and network/ssl stacks and keep running into this. It is always on data coming in from freeswitch on the websocket connection, and its very very random. Sometimes I will get it 20 times in a row, other times it takes thousands of connections/sessions before it happen. It also, obviously, completely goes away if I use plain ws instead wss.
Here are the errors: python: SSLError: [SSL: DECRYPTION_FAILED_OR_BAD_RECORD_MAC] decryption failed or bad record mac (_ssl.c:1750) c/c++ (stunnel4): SSL_read: 1408F119: error:1408F119:SSL routines:SSL3_GET_RECORD:decryption failed or bad record mac Java: java.lang.IllegalArgumentException: Bad arguments at javax.crypto.Mac.update(Mac.java:509) at sun.security.ssl.MAC.compute(MAC.java:135) at sun.security.ssl.InputRecord.checkMacTags(InputRecord.java:265) at sun.security.ssl.InputRecord.decrypt(InputRecord.java:216) at sun.security.ssl.EngineInputRecord.decrypt(EngineInputRecord.java:177) at sun.security.ssl.SSLEngineImpl.readRecord(SSLEngineImpl.java:974) at sun.security.ssl.SSLEngineImpl.readNetRecord(SSLEngineImpl.java:907) at sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:781) at javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:624)
Attached are a simple python script to do the load, my dialplan and sip_profile. The python script can take a few runs before it see the error, and I know its not completing the sip or rtp, but even if it does this still happens.
I have also looked at libsofia-sip-ua/tport/ws.c and I dont see anything obvious. I am getting setup to build v1.6 head and test this any guidance on ways I can trouble shoot this better or requests for more info are very welcome.
Its just in our isolated lab, pretty normal dell xeon server running Jessie 8.6. I just want to get it building on the same box I am testing with so setting that all up. I was able to reproduce it w/o DTLS/Srtp. here is a much simpler and cleaned up version of the python script. On Thu, May 11, 2017 at 4:34 PM, Michael Jerris <mike@jerris.com> wrote:
what is “this environment” ?
On May 11, 2017, at 6:31 PM, Luke Wahlmeier <lwahlmeier@gmail.com> wrote:
Yeah I can usually get it to happen within about 5 minutes or so of testing. Still getting all setup to build freeswitch in this environment, but I should have it working by tomorrow. I will try more w/o dtls/srtp as well and make sure it does not need to be on.
Thanks Luke
On Thu, May 11, 2017 at 4:20 PM, Michael Jerris <mike@jerris.com> wrote:
if you can reproduce this reliably, i’d try master as well. Unless this is a bug in openssl, i can’t imagine how dtls would come into play in something like this.
On May 11, 2017, at 5:48 PM, Luke Wahlmeier <lwahlmeier@gmail.com> wrote:
I keep semi-regularly running into issues using the wss transport when using dtls/strp/ice. This is on the latest 1.6.17~34~0fc0946 on Debian jessie, but I am pretty sure it was happening on the last couple releases as well.
It seems like something bad/wrong happens to the encrypted data going over the websocket coming from freeswitch when more then 1 websocket connection are going and so far ice/srtp/dtls also seem to be needed in the invite to duplicate it.
I have tried many different languages and network/ssl stacks and keep running into this. It is always on data coming in from freeswitch on the websocket connection, and its very very random. Sometimes I will get it 20 times in a row, other times it takes thousands of connections/sessions before it happen. It also, obviously, completely goes away if I use plain ws instead wss.
Here are the errors: python: SSLError: [SSL: DECRYPTION_FAILED_OR_BAD_RECORD_MAC] decryption failed or bad record mac (_ssl.c:1750) c/c++ (stunnel4): SSL_read: 1408F119: error:1408F119:SSL routines:SSL3_GET_RECORD:decryption failed or bad record mac Java: java.lang.IllegalArgumentException: Bad arguments at javax.crypto.Mac.update(Mac.java:509) at sun.security.ssl.MAC.compute(MAC.java:135) at sun.security.ssl.InputRecord.checkMacTags(InputRecord.java:265) at sun.security.ssl.InputRecord.decrypt(InputRecord.java:216) at sun.security.ssl.EngineInputRecord.decrypt(EngineInputRecord .java:177) at sun.security.ssl.SSLEngineImpl.readRecord(SSLEngineImpl. java:974) at sun.security.ssl.SSLEngineImpl.readNetRecord(SSLEngineImpl. java:907) at sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:781) at javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:624)
Attached are a simple python script to do the load, my dialplan and sip_profile. The python script can take a few runs before it see the error, and I know its not completing the sip or rtp, but even if it does this still happens.
I have also looked at libsofia-sip-ua/tport/ws.c and I dont see anything obvious. I am getting setup to build v1.6 head and test this any guidance on ways I can trouble shoot this better or requests for more info are very welcome.
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
Official FreeSWITCH Sites http://www.freeswitch.org http://confluence.freeswitch.org http://www.cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
Just got done testing this on v1.6 head and master, both seem to still have this issue. This box is using libssl version 1.0.1t-1+deb8u6. I am gonna start digging more into the ws/wss/sofia code to see if I can figure it out. Any suggestions on debugging this would be appreciated. Thanks Luke On Thu, May 11, 2017 at 5:12 PM, Luke Wahlmeier <lwahlmeier@gmail.com> wrote:
Its just in our isolated lab, pretty normal dell xeon server running Jessie 8.6. I just want to get it building on the same box I am testing with so setting that all up.
I was able to reproduce it w/o DTLS/Srtp. here is a much simpler and cleaned up version of the python script.
On Thu, May 11, 2017 at 4:34 PM, Michael Jerris <mike@jerris.com> wrote:
what is “this environment” ?
On May 11, 2017, at 6:31 PM, Luke Wahlmeier <lwahlmeier@gmail.com> wrote:
Yeah I can usually get it to happen within about 5 minutes or so of testing. Still getting all setup to build freeswitch in this environment, but I should have it working by tomorrow. I will try more w/o dtls/srtp as well and make sure it does not need to be on.
Thanks Luke
On Thu, May 11, 2017 at 4:20 PM, Michael Jerris <mike@jerris.com> wrote:
if you can reproduce this reliably, i’d try master as well. Unless this is a bug in openssl, i can’t imagine how dtls would come into play in something like this.
On May 11, 2017, at 5:48 PM, Luke Wahlmeier <lwahlmeier@gmail.com> wrote:
I keep semi-regularly running into issues using the wss transport when using dtls/strp/ice. This is on the latest 1.6.17~34~0fc0946 on Debian jessie, but I am pretty sure it was happening on the last couple releases as well.
It seems like something bad/wrong happens to the encrypted data going over the websocket coming from freeswitch when more then 1 websocket connection are going and so far ice/srtp/dtls also seem to be needed in the invite to duplicate it.
I have tried many different languages and network/ssl stacks and keep running into this. It is always on data coming in from freeswitch on the websocket connection, and its very very random. Sometimes I will get it 20 times in a row, other times it takes thousands of connections/sessions before it happen. It also, obviously, completely goes away if I use plain ws instead wss.
Here are the errors: python: SSLError: [SSL: DECRYPTION_FAILED_OR_BAD_RECORD_MAC] decryption failed or bad record mac (_ssl.c:1750) c/c++ (stunnel4): SSL_read: 1408F119: error:1408F119:SSL routines:SSL3_GET_RECORD:decryption failed or bad record mac Java: java.lang.IllegalArgumentException: Bad arguments at javax.crypto.Mac.update(Mac.java:509) at sun.security.ssl.MAC.compute(MAC.java:135) at sun.security.ssl.InputRecord.checkMacTags(InputRecord.java:265) at sun.security.ssl.InputRecord.decrypt(InputRecord.java:216) at sun.security.ssl.EngineInputRecord.decrypt(EngineInputRecord .java:177) at sun.security.ssl.SSLEngineImpl.readRecord(SSLEngineImpl.java :974) at sun.security.ssl.SSLEngineImpl.readNetRecord(SSLEngineImpl.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@freeswitch.org http://www.freeswitchsolutions.com
Official FreeSWITCH Sites http://www.freeswitch.org http://confluence.freeswitch.org http://www.cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
test on master.. work a similar test for verto maybe, this might have to do with sip specifically trying to keep state. Might make sense to build something out of libks as it has basically the same web socket code, and has both client and server web socket support in it, to do a “real” test”, instead of this fake sip without any state over web sockets.
On May 12, 2017, at 11:42 AM, Luke Wahlmeier <lwahlmeier@gmail.com> wrote:
Just got done testing this on v1.6 head and master, both seem to still have this issue. This box is using libssl version 1.0.1t-1+deb8u6. I am gonna start digging more into the ws/wss/sofia code to see if I can figure it out. Any suggestions on debugging this would be appreciated.
Thanks Luke
On Thu, May 11, 2017 at 5:12 PM, Luke Wahlmeier <lwahlmeier@gmail.com <mailto:lwahlmeier@gmail.com>> wrote: Its just in our isolated lab, pretty normal dell xeon server running Jessie 8.6. I just want to get it building on the same box I am testing with so setting that all up.
I was able to reproduce it w/o DTLS/Srtp. here is a much simpler and cleaned up version of the python script.
On Thu, May 11, 2017 at 4:34 PM, Michael Jerris <mike@jerris.com <mailto:mike@jerris.com>> wrote: what is “this environment” ?
On May 11, 2017, at 6:31 PM, Luke Wahlmeier <lwahlmeier@gmail.com <mailto:lwahlmeier@gmail.com>> wrote:
Yeah I can usually get it to happen within about 5 minutes or so of testing. Still getting all setup to build freeswitch in this environment, but I should have it working by tomorrow. I will try more w/o dtls/srtp as well and make sure it does not need to be on.
Thanks Luke
On Thu, May 11, 2017 at 4:20 PM, Michael Jerris <mike@jerris.com <mailto:mike@jerris.com>> wrote: if you can reproduce this reliably, i’d try master as well. Unless this is a bug in openssl, i can’t imagine how dtls would come into play in something like this.
On May 11, 2017, at 5:48 PM, Luke Wahlmeier <lwahlmeier@gmail.com <mailto:lwahlmeier@gmail.com>> wrote:
I keep semi-regularly running into issues using the wss transport when using dtls/strp/ice. This is on the latest 1.6.17~34~0fc0946 on Debian jessie, but I am pretty sure it was happening on the last couple releases as well.
It seems like something bad/wrong happens to the encrypted data going over the websocket coming from freeswitch when more then 1 websocket connection are going and so far ice/srtp/dtls also seem to be needed in the invite to duplicate it.
I have tried many different languages and network/ssl stacks and keep running into this. It is always on data coming in from freeswitch on the websocket connection, and its very very random. Sometimes I will get it 20 times in a row, other times it takes thousands of connections/sessions before it happen. It also, obviously, completely goes away if I use plain ws instead wss.
Here are the errors: python: SSLError: [SSL: DECRYPTION_FAILED_OR_BAD_RECORD_MAC] decryption failed or bad record mac (_ssl.c:1750) c/c++ (stunnel4): SSL_read: 1408F119: error:1408F119:SSL routines:SSL3_GET_RECORD:decryption failed or bad record mac Java: java.lang.IllegalArgumentException: Bad arguments at javax.crypto.Mac.update(Mac.java:509) at sun.security.ssl.MAC.compute(MAC.java:135) at sun.security.ssl.InputRecord.checkMacTags(InputRecord.java:265) at sun.security.ssl.InputRecord.decrypt(InputRecord.java:216) at sun.security.ssl.EngineInputRecord.decrypt(EngineInputRecord.java:177) at sun.security.ssl.SSLEngineImpl.readRecord(SSLEngineImpl.java:974) at sun.security.ssl.SSLEngineImpl.readNetRecord(SSLEngineImpl.java:907) at sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:781) at javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:624)
Attached are a simple python script to do the load, my dialplan and sip_profile. The python script can take a few runs before it see the error, and I know its not completing the sip or rtp, but even if it does this still happens.
I have also looked at libsofia-sip-ua/tport/ws.c and I dont see anything obvious. I am getting setup to build v1.6 head and test this any guidance on ways I can trouble shoot this better or requests for more info are very welcome.
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org <mailto:consulting@freeswitch.org> http://www.freeswitchsolutions.com <http://www.freeswitchsolutions.com/>
Official FreeSWITCH Sites http://www.freeswitch.org <http://www.freeswitch.org/> http://confluence.freeswitch.org <http://confluence.freeswitch.org/> http://www.cluecon.com <http://www.cluecon.com/>
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org <mailto:FreeSWITCH-users@lists.freeswitch.org> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users <http://lists.freeswitch.org/mailman/listinfo/freeswitch-users> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users <http://lists.freeswitch.org/mailman/options/freeswitch-users> http://www.freeswitch.org <http://www.freeswitch.org/>
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
Official FreeSWITCH Sites http://www.freeswitch.org http://confluence.freeswitch.org http://www.cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
Thanks Michael, I am more then happy to setup something with libks if needed. I have figured out some more however. It appears that this only happens when a wss connections session has not fully established and is cleaning up because of timing out. The problem is that it causes another wss connection it to get this ssl error, even if that other wss connection has a fully established and running audio session. It is important to note it does not seem to interrupt audio just the wss sip channel, which I am fairly sure can be reestablished for that audio session w/o an issue. The sessions that is being cleaned up sends the logs messages as its doing it: 2017-05-12 17:32:46.607768 [NOTICE] sofia.c:8438 Hangup sofia/websocket/nobody@1LF3F6I924P9WH6U [CS_EXECUTE] [NORMAL_UNSPECIFIED] 2017-05-12 17:32:46.627768 [INFO] conference_loop.c:1621 Channel leaving conference, cause: NORMAL_UNSPECIFIED 2017-05-12 17:32:46.627768 [NOTICE] switch_core_session.c:1730 Session 46 (sofia/websocket/nobody@1LF3F6I924P9WH6U) Ended 2017-05-12 17:32:46.627768 [NOTICE] switch_core_session.c:1734 Close Channel sofia/websocket/nobody@1LF3F6I924P9WH6U [CS_DESTROY] I have attached the updated python script, it can duplicate this every time now with only 2 connections. I verified with a webRTC client that if I initiate this first connection in the script, let it close, then connect the webRTC client and get full audio, once the first session from the script times out it causes the webRTC wss connection to get an error and close. The webRTC connection is in chrome with sip.js. Sorry the python script is so nasty, was working through any possible duplicated sip session stuff in it to make sure that was not why it was hitting the second connection. On Fri, May 12, 2017 at 10:20 AM, Michael Jerris <mike@jerris.com> wrote:
test on master.. work a similar test for verto maybe, this might have to do with sip specifically trying to keep state. Might make sense to build something out of libks as it has basically the same web socket code, and has both client and server web socket support in it, to do a “real” test”, instead of this fake sip without any state over web sockets.
On May 12, 2017, at 11:42 AM, Luke Wahlmeier <lwahlmeier@gmail.com> wrote:
Just got done testing this on v1.6 head and master, both seem to still have this issue. This box is using libssl version 1.0.1t-1+deb8u6. I am gonna start digging more into the ws/wss/sofia code to see if I can figure it out. Any suggestions on debugging this would be appreciated.
Thanks Luke
On Thu, May 11, 2017 at 5:12 PM, Luke Wahlmeier <lwahlmeier@gmail.com> wrote:
Its just in our isolated lab, pretty normal dell xeon server running Jessie 8.6. I just want to get it building on the same box I am testing with so setting that all up.
I was able to reproduce it w/o DTLS/Srtp. here is a much simpler and cleaned up version of the python script.
On Thu, May 11, 2017 at 4:34 PM, Michael Jerris <mike@jerris.com> wrote:
what is “this environment” ?
On May 11, 2017, at 6:31 PM, Luke Wahlmeier <lwahlmeier@gmail.com> wrote:
Yeah I can usually get it to happen within about 5 minutes or so of testing. Still getting all setup to build freeswitch in this environment, but I should have it working by tomorrow. I will try more w/o dtls/srtp as well and make sure it does not need to be on.
Thanks Luke
On Thu, May 11, 2017 at 4:20 PM, Michael Jerris <mike@jerris.com> wrote:
if you can reproduce this reliably, i’d try master as well. Unless this is a bug in openssl, i can’t imagine how dtls would come into play in something like this.
On May 11, 2017, at 5:48 PM, Luke Wahlmeier <lwahlmeier@gmail.com> wrote:
I keep semi-regularly running into issues using the wss transport when using dtls/strp/ice. This is on the latest 1.6.17~34~0fc0946 on Debian jessie, but I am pretty sure it was happening on the last couple releases as well.
It seems like something bad/wrong happens to the encrypted data going over the websocket coming from freeswitch when more then 1 websocket connection are going and so far ice/srtp/dtls also seem to be needed in the invite to duplicate it.
I have tried many different languages and network/ssl stacks and keep running into this. It is always on data coming in from freeswitch on the websocket connection, and its very very random. Sometimes I will get it 20 times in a row, other times it takes thousands of connections/sessions before it happen. It also, obviously, completely goes away if I use plain ws instead wss.
Here are the errors: python: SSLError: [SSL: DECRYPTION_FAILED_OR_BAD_RECORD_MAC] decryption failed or bad record mac (_ssl.c:1750) c/c++ (stunnel4): SSL_read: 1408F119: error:1408F119:SSL routines:SSL3_GET_RECORD:decryption failed or bad record mac Java: java.lang.IllegalArgumentException: Bad arguments at javax.crypto.Mac.update(Mac.java:509) at sun.security.ssl.MAC.compute(MAC.java:135) at sun.security.ssl.InputRecord.checkMacTags(InputRecord.java:2
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@freeswitch.org http://www.freeswitchsolutions.com
Official FreeSWITCH Sites http://www.freeswitch.org http://confluence.freeswitch.org http://www.cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
Official FreeSWITCH Sites http://www.freeswitch.org http://confluence.freeswitch.org http://www.cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
Official FreeSWITCH Sites http://www.freeswitch.org http://confluence.freeswitch.org http://www.cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
Here is the debug logs from this happening: f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [NOTICE] switch_channel.c:1104 New Channel sofia/websocket/nobody@52LX8LP8BBWG6990 [f9a97c98-373b-11e7-9136-499bb33ea37e] f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@52LX8LP8BBWG6990) Running State Change CS_NEW (Cur 1 Tot 1) f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] sofia.c:10028 sofia/websocket/nobody@52LX8LP8BBWG6990 receiving invite from 192.168.56.151:53442 version: 1.9.0 git db24869 2017-05-11 18:22:45Z 64bit f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] sofia.c:11325 Setting NAT mode based on websockets f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] sofia.c:7247 Channel sofia/websocket/nobody@52LX8LP8BBWG6990 entering state [received][100] f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] sofia.c:7257 Remote SDP: f9a97c98-373b-11e7-9136-499bb33ea37e v=0 f9a97c98-373b-11e7-9136-499bb33ea37e o=- 196478633 2 IN IP4 192.168.56.151 f9a97c98-373b-11e7-9136-499bb33ea37e s=- f9a97c98-373b-11e7-9136-499bb33ea37e c=IN IP4 192.168.56.151 f9a97c98-373b-11e7-9136-499bb33ea37e t=0 0 f9a97c98-373b-11e7-9136-499bb33ea37e m=audio 42504 RTP/AVP 0 100 f9a97c98-373b-11e7-9136-499bb33ea37e a=rtpmap:0 PCMU/8000 f9a97c98-373b-11e7-9136-499bb33ea37e a=maxptime:20 f9a97c98-373b-11e7-9136-499bb33ea37e f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_media.c:5165 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [:100:0:20:0:1]/[PCMU:0:8000:20:64000:1] f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_media.c:3425 Set Codec sofia/websocket/nobody@52LX8LP8BBWG6990 PCMU/8000 20 ms 160 samples 64000 bits 1 channels f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_codec.c:111 sofia/websocket/nobody@52LX8LP8BBWG6990 Original read codec set to PCMU:0 f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_media.c:5398 No 2833 in SDP. Liberal DTMF mode adding 101 as telephone-event. f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_media.c:5427 sofia/websocket/nobody@52LX8LP8BBWG6990 Set 2833 dtmf send payload to 101 recv payload to 101 f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] sofia.c:7670 (sofia/websocket/nobody@52LX8LP8BBWG6990) State Change CS_NEW -> CS_INIT f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_state_machine.c:603 (sofia/websocket/nobody@52LX8LP8BBWG6990) State NEW f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@52LX8LP8BBWG6990) Running State Change CS_INIT (Cur 1 Tot 1) f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_state_machine.c:627 (sofia/websocket/nobody@52LX8LP8BBWG6990) State INIT f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] mod_sofia.c:93 sofia/websocket/nobody@52LX8LP8BBWG6990 SOFIA INIT f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_state_machine.c:40 sofia/websocket/nobody@52LX8LP8BBWG6990 Standard INIT f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:48 (sofia/websocket/nobody@52LX8LP8BBWG6990) State Change CS_INIT -> CS_ROUTING f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:627 (sofia/websocket/nobody@52LX8LP8BBWG6990) State INIT going to sleep f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@52LX8LP8BBWG6990) Running State Change CS_ROUTING (Cur 1 Tot 1) f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_channel.c:2249 (sofia/websocket/nobody@52LX8LP8BBWG6990) Callstate Change DOWN -> RINGING f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:643 (sofia/websocket/nobody@52LX8LP8BBWG6990) State ROUTING f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] mod_sofia.c:154 sofia/websocket/nobody@52LX8LP8BBWG6990 SOFIA ROUTING f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:236 sofia/websocket/nobody@52LX8LP8BBWG6990 Standard ROUTING f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [INFO] mod_dialplan_xml.c:637 Processing unknown <>->52LX8LP8BBWG6990 in context wss-dialplan f9a97c98-373b-11e7-9136-499bb33ea37e Dialplan: sofia/websocket/nobody@52LX8LP8BBWG6990 parsing [wss-dialplan->wss-dialplan] continue=false f9a97c98-373b-11e7-9136-499bb33ea37e Dialplan: sofia/websocket/nobody@52LX8LP8BBWG6990 Regex (PASS) [wss-dialplan] destination_number(52LX8LP8BBWG6990) =~ /.+/ break=on-false f9a97c98-373b-11e7-9136-499bb33ea37e Dialplan: sofia/websocket/nobody@52LX8LP8BBWG6990 Action conference(test123) f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:286 (sofia/websocket/nobody@52LX8LP8BBWG6990) State Change CS_ROUTING -> CS_EXECUTE f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:643 (sofia/websocket/nobody@52LX8LP8BBWG6990) State ROUTING going to sleep f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@52LX8LP8BBWG6990) Running State Change CS_EXECUTE (Cur 1 Tot 1) f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:650 (sofia/websocket/nobody@52LX8LP8BBWG6990) State EXECUTE f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] mod_sofia.c:209 sofia/websocket/nobody@52LX8LP8BBWG6990 SOFIA EXECUTE f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:328 sofia/websocket/nobody@52LX8LP8BBWG6990 Standard EXECUTE f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_session.c:2707 Application conference Requires media! pre_answering channel sofia/websocket/nobody@52LX8LP8BBWG6990 f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [INFO] switch_core_session.c:2709 Sending early media f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_media.c:8144 AUDIO RTP [sofia/websocket/nobody@52LX8LP8BBWG6990] 172.16.19.215 port 27662 -> 192.168.56.151 port 42504 codec: 0 ms: 20 f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_rtp.c:4096 Starting timer [soft] 160 bytes per 20ms f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_media.c:8447 sofia/websocket/nobody@52LX8LP8BBWG6990 Set 2833 dtmf send payload to 101 f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_media.c:8454 sofia/websocket/nobody@52LX8LP8BBWG6990 Set 2833 dtmf receive payload to 101 f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_media.c:8477 sofia/websocket/nobody@52LX8LP8BBWG6990 Set rtp dtmf delay to 40 f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] mod_sofia.c:2512 Ring SDP: f9a97c98-373b-11e7-9136-499bb33ea37e v=0 f9a97c98-373b-11e7-9136-499bb33ea37e o=FreeSWITCH 1494583976 1494583977 IN IP4 172.16.19.215 f9a97c98-373b-11e7-9136-499bb33ea37e s=FreeSWITCH f9a97c98-373b-11e7-9136-499bb33ea37e c=IN IP4 172.16.19.215 f9a97c98-373b-11e7-9136-499bb33ea37e t=0 0 f9a97c98-373b-11e7-9136-499bb33ea37e m=audio 27662 RTP/AVP 0 101 f9a97c98-373b-11e7-9136-499bb33ea37e a=rtpmap:0 PCMU/8000 f9a97c98-373b-11e7-9136-499bb33ea37e a=rtpmap:101 telephone-event/8000 f9a97c98-373b-11e7-9136-499bb33ea37e a=fmtp:101 0-16 f9a97c98-373b-11e7-9136-499bb33ea37e a=ptime:20 f9a97c98-373b-11e7-9136-499bb33ea37e a=sendrecv f9a97c98-373b-11e7-9136-499bb33ea37e f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [NOTICE] mod_sofia.c:2515 Pre-Answer sofia/websocket/nobody@52LX8LP8BBWG6990! f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_channel.c:3481 (sofia/websocket/nobody@52LX8LP8BBWG6990) Callstate Change RINGING -> EARLY f9a97c98-373b-11e7-9136-499bb33ea37e EXECUTE sofia/websocket/nobody@52LX8LP8BBWG6990 conference(test123) f9a97c98-373b-11e7-9136-499bb33ea37e v=0 f9a97c98-373b-11e7-9136-499bb33ea37e o=FreeSWITCH 1494583976 1494583978 IN IP4 172.16.19.215 f9a97c98-373b-11e7-9136-499bb33ea37e s=FreeSWITCH f9a97c98-373b-11e7-9136-499bb33ea37e c=IN IP4 172.16.19.215 f9a97c98-373b-11e7-9136-499bb33ea37e t=0 0 f9a97c98-373b-11e7-9136-499bb33ea37e m=audio 27662 RTP/AVP 0 101 f9a97c98-373b-11e7-9136-499bb33ea37e a=rtpmap:0 PCMU/8000 f9a97c98-373b-11e7-9136-499bb33ea37e a=rtpmap:101 telephone-event/8000 f9a97c98-373b-11e7-9136-499bb33ea37e a=fmtp:101 0-16 f9a97c98-373b-11e7-9136-499bb33ea37e a=ptime:20 f9a97c98-373b-11e7-9136-499bb33ea37e a=sendrecv f9a97c98-373b-11e7-9136-499bb33ea37e f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] sofia.c:7247 Channel sofia/websocket/nobody@52LX8LP8BBWG6990 entering state [early][183] f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [NOTICE] mod_conference.c:1829 Channel [sofia/websocket/nobody@52LX8LP8BBWG6990] has been answered f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_channel.c:3780 (sofia/websocket/nobody@52LX8LP8BBWG6990) Callstate Change EARLY -> ACTIVE f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] sofia.c:7247 Channel sofia/websocket/nobody@52LX8LP8BBWG6990 entering state [completed][200] 2017-05-12 17:53:58.932851 [DEBUG] mod_conference.c:3289 using channel sound prefix: /tmp/fs1.8/share/freeswitch/sounds/en/us/callie f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] conference_member.c:1715 Raw Codec Activation Success L16@8000hz 1 channel 20ms f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] conference_member.c:1762 Raw Codec Activation Success L16@8000hz 1 channel 20ms f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_codec.c:223 sofia/websocket/nobody@52LX8LP8BBWG6990 Push codec L16:100 2017-05-12 17:53:58.932851 [DEBUG] mod_conference.c:227 Setup timer success interval: 20 samples: 160 2017-05-12 17:53:58.932851 [ERR] switch_core_video.c:2868 This function is not available, libpng not installed f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] conference_loop.c:1306 Setup timer soft success interval: 20 samples: 160 from codec PCMU 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [NOTICE] switch_channel.c:1104 New Channel sofia/websocket/nobody@3PXT9NIJPMV6KC8W [02b30be2-373c-11e7-913a-499bb33ea37e] 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Running State Change CS_NEW (Cur 2 Tot 2) 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] sofia.c:10028 sofia/websocket/nobody@3PXT9NIJPMV6KC8W receiving invite from 192.168.56.151:53568 version: 1.9.0 git db24869 2017-05-11 18:22:45Z 64bit 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] sofia.c:11325 Setting NAT mode based on websockets 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] sofia.c:7247 Channel sofia/websocket/nobody@3PXT9NIJPMV6KC8W entering state [received][100] 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] sofia.c:7257 Remote SDP: 02b30be2-373c-11e7-913a-499bb33ea37e v=0 02b30be2-373c-11e7-913a-499bb33ea37e o=- 716582477 2 IN IP4 192.168.56.151 02b30be2-373c-11e7-913a-499bb33ea37e s=- 02b30be2-373c-11e7-913a-499bb33ea37e c=IN IP4 192.168.56.151 02b30be2-373c-11e7-913a-499bb33ea37e t=0 0 02b30be2-373c-11e7-913a-499bb33ea37e m=audio 11866 RTP/AVP 0 100 02b30be2-373c-11e7-913a-499bb33ea37e a=rtpmap:0 PCMU/8000 02b30be2-373c-11e7-913a-499bb33ea37e a=maxptime:20 02b30be2-373c-11e7-913a-499bb33ea37e 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:5165 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [:100:0:20:0:1]/[PCMU:0:8000:20:64000:1] 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:3425 Set Codec sofia/websocket/nobody@3PXT9NIJPMV6KC8W PCMU/8000 20 ms 160 samples 64000 bits 1 channels 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_codec.c:111 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Original read codec set to PCMU:0 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:5398 No 2833 in SDP. Liberal DTMF mode adding 101 as telephone-event. 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:5427 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Set 2833 dtmf send payload to 101 recv payload to 101 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] sofia.c:7670 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State Change CS_NEW -> CS_INIT 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:603 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State NEW 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Running State Change CS_INIT (Cur 2 Tot 2) 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:627 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State INIT 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] mod_sofia.c:93 sofia/websocket/nobody@3PXT9NIJPMV6KC8W SOFIA INIT 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:40 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Standard INIT 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:48 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State Change CS_INIT -> CS_ROUTING 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:627 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State INIT going to sleep 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Running State Change CS_ROUTING (Cur 2 Tot 2) 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_channel.c:2249 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Callstate Change DOWN -> RINGING 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:643 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State ROUTING 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] mod_sofia.c:154 sofia/websocket/nobody@3PXT9NIJPMV6KC8W SOFIA ROUTING 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:236 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Standard ROUTING 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [INFO] mod_dialplan_xml.c:637 Processing unknown <>->3PXT9NIJPMV6KC8W in context wss-dialplan 02b30be2-373c-11e7-913a-499bb33ea37e Dialplan: sofia/websocket/nobody@3PXT9NIJPMV6KC8W parsing [wss-dialplan->wss-dialplan] continue=false 02b30be2-373c-11e7-913a-499bb33ea37e Dialplan: sofia/websocket/nobody@3PXT9NIJPMV6KC8W Regex (PASS) [wss-dialplan] destination_number(3PXT9NIJPMV6KC8W) =~ /.+/ break=on-false 02b30be2-373c-11e7-913a-499bb33ea37e Dialplan: sofia/websocket/nobody@3PXT9NIJPMV6KC8W Action conference(test123) 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:286 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State Change CS_ROUTING -> CS_EXECUTE 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:643 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State ROUTING going to sleep 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Running State Change CS_EXECUTE (Cur 2 Tot 2) 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:650 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State EXECUTE 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] mod_sofia.c:209 sofia/websocket/nobody@3PXT9NIJPMV6KC8W SOFIA EXECUTE 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:328 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Standard EXECUTE 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_session.c:2707 Application conference Requires media! pre_answering channel sofia/websocket/nobody@3PXT9NIJPMV6KC8W 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [INFO] switch_core_session.c:2709 Sending early media 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:8144 AUDIO RTP [sofia/websocket/nobody@3PXT9NIJPMV6KC8W] 172.16.19.215 port 28858 -> 192.168.56.151 port 11866 codec: 0 ms: 20 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_rtp.c:4096 Starting timer [soft] 160 bytes per 20ms 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:8447 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Set 2833 dtmf send payload to 101 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:8454 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Set 2833 dtmf receive payload to 101 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:8477 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Set rtp dtmf delay to 40 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] mod_sofia.c:2512 Ring SDP: 02b30be2-373c-11e7-913a-499bb33ea37e v=0 02b30be2-373c-11e7-913a-499bb33ea37e o=FreeSWITCH 1494582796 1494582797 IN IP4 172.16.19.215 02b30be2-373c-11e7-913a-499bb33ea37e s=FreeSWITCH 02b30be2-373c-11e7-913a-499bb33ea37e c=IN IP4 172.16.19.215 02b30be2-373c-11e7-913a-499bb33ea37e t=0 0 02b30be2-373c-11e7-913a-499bb33ea37e m=audio 28858 RTP/AVP 0 101 02b30be2-373c-11e7-913a-499bb33ea37e a=rtpmap:0 PCMU/8000 02b30be2-373c-11e7-913a-499bb33ea37e a=rtpmap:101 telephone-event/8000 02b30be2-373c-11e7-913a-499bb33ea37e a=fmtp:101 0-16 02b30be2-373c-11e7-913a-499bb33ea37e a=ptime:20 02b30be2-373c-11e7-913a-499bb33ea37e a=sendrecv 02b30be2-373c-11e7-913a-499bb33ea37e 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [NOTICE] mod_sofia.c:2515 Pre-Answer sofia/websocket/nobody@3PXT9NIJPMV6KC8W! 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_channel.c:3481 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Callstate Change RINGING -> EARLY 02b30be2-373c-11e7-913a-499bb33ea37e EXECUTE sofia/websocket/nobody@3PXT9NIJPMV6KC8W conference(test123) 02b30be2-373c-11e7-913a-499bb33ea37e v=0 02b30be2-373c-11e7-913a-499bb33ea37e o=FreeSWITCH 1494582796 1494582798 IN IP4 172.16.19.215 02b30be2-373c-11e7-913a-499bb33ea37e s=FreeSWITCH 02b30be2-373c-11e7-913a-499bb33ea37e c=IN IP4 172.16.19.215 02b30be2-373c-11e7-913a-499bb33ea37e t=0 0 02b30be2-373c-11e7-913a-499bb33ea37e m=audio 28858 RTP/AVP 0 101 02b30be2-373c-11e7-913a-499bb33ea37e a=rtpmap:0 PCMU/8000 02b30be2-373c-11e7-913a-499bb33ea37e a=rtpmap:101 telephone-event/8000 02b30be2-373c-11e7-913a-499bb33ea37e a=fmtp:101 0-16 02b30be2-373c-11e7-913a-499bb33ea37e a=ptime:20 02b30be2-373c-11e7-913a-499bb33ea37e a=sendrecv 02b30be2-373c-11e7-913a-499bb33ea37e 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] sofia.c:7247 Channel sofia/websocket/nobody@3PXT9NIJPMV6KC8W entering state [early][183] 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [NOTICE] mod_conference.c:1829 Channel [sofia/websocket/nobody@3PXT9NIJPMV6KC8W] has been answered 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_channel.c:3780 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Callstate Change EARLY -> ACTIVE 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] sofia.c:7247 Channel sofia/websocket/nobody@3PXT9NIJPMV6KC8W entering state [completed][200] 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] conference_member.c:1715 Raw Codec Activation Success L16@8000hz 1 channel 20ms 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] conference_member.c:1762 Raw Codec Activation Success L16@8000hz 1 channel 20ms 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_codec.c:223 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Push codec L16:100 2017-05-12 17:54:14.092839 [ERR] switch_core_video.c:2868 This function is not available, libpng not installed 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] conference_loop.c:1306 Setup timer soft success interval: 20 samples: 160 from codec PCMU This is where session 02b30be2-373c-11e7-913a-499bb33ea37e wss socket gets an ssl errror: f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.952843 [DEBUG] sofia.c:7247 Channel sofia/websocket/nobody@52LX8LP8BBWG6990 entering state [terminating][0] f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.952843 [NOTICE] sofia.c:8438 Hangup sofia/websocket/nobody@52LX8LP8BBWG6990 [CS_EXECUTE] [NORMAL_UNSPECIFIED] f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [INFO] conference_loop.c:1621 Channel leaving conference, cause: NORMAL_UNSPECIFIED f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] mod_conference.c:2404 sofia/websocket/nobody@52LX8LP8BBWG6990 skip receive message [TRANSFER] (channel is hungup already) f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_media.c:11838 sofia/websocket/nobody@52LX8LP8BBWG6990 skip receive message [BITRATE_REQ] (channel is hungup already) f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_codec.c:248 sofia/websocket/nobody@52LX8LP8BBWG6990 Restore previous codec PCMU:0. f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_session.c:2884 sofia/websocket/nobody@52LX8LP8BBWG6990 skip receive message [PHONE_EVENT] (channel is hungup already) f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:650 (sofia/websocket/nobody@52LX8LP8BBWG6990) State EXECUTE going to sleep f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@52LX8LP8BBWG6990) Running State Change CS_HANGUP (Cur 2 Tot 2) f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:850 (sofia/websocket/nobody@52LX8LP8BBWG6990) Callstate Change ACTIVE -> HANGUP f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:852 (sofia/websocket/nobody@52LX8LP8BBWG6990) State HANGUP f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] mod_sofia.c:449 Channel sofia/websocket/nobody@52LX8LP8BBWG6990 hanging up, cause: NORMAL_UNSPECIFIED f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:60 sofia/websocket/nobody@52LX8LP8BBWG6990 Standard HANGUP, cause: NORMAL_UNSPECIFIED f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:852 (sofia/websocket/nobody@52LX8LP8BBWG6990) State HANGUP going to sleep f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:619 (sofia/websocket/nobody@52LX8LP8BBWG6990) State Change CS_HANGUP -> CS_REPORTING f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@52LX8LP8BBWG6990) Running State Change CS_REPORTING (Cur 2 Tot 2) f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:938 (sofia/websocket/nobody@52LX8LP8BBWG6990) State REPORTING f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:174 sofia/websocket/nobody@52LX8LP8BBWG6990 Standard REPORTING, cause: NORMAL_UNSPECIFIED f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:938 (sofia/websocket/nobody@52LX8LP8BBWG6990) State REPORTING going to sleep f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:610 (sofia/websocket/nobody@52LX8LP8BBWG6990) State Change CS_REPORTING -> CS_DESTROY f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_session.c:1712 Session 1 (sofia/websocket/nobody@52LX8LP8BBWG6990) Locked, Waiting on external entities f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [NOTICE] switch_core_session.c:1730 Session 1 (sofia/websocket/nobody@52LX8LP8BBWG6990) Ended f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [NOTICE] switch_core_session.c:1734 Close Channel sofia/websocket/nobody@52LX8LP8BBWG6990 [CS_DESTROY] f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:741 (sofia/websocket/nobody@52LX8LP8BBWG6990) Running State Change CS_DESTROY (Cur 1 Tot 2) f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:751 (sofia/websocket/nobody@52LX8LP8BBWG6990) State DESTROY f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] mod_sofia.c:354 sofia/websocket/nobody@52LX8LP8BBWG6990 SOFIA DESTROY f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:181 sofia/websocket/nobody@52LX8LP8BBWG6990 Standard DESTROY f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:751 (sofia/websocket/nobody@52LX8LP8BBWG6990) State DESTROY going to sleep 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.112842 [DEBUG] sofia.c:7247 Channel sofia/websocket/nobody@3PXT9NIJPMV6KC8W entering state [terminating][0] 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.112842 [NOTICE] sofia.c:8438 Hangup sofia/websocket/nobody@3PXT9NIJPMV6KC8W [CS_EXECUTE] [NORMAL_UNSPECIFIED] 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [INFO] conference_loop.c:1621 Channel leaving conference, cause: NORMAL_UNSPECIFIED 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] mod_conference.c:2404 sofia/websocket/nobody@3PXT9NIJPMV6KC8W skip receive message [TRANSFER] (channel is hungup already) 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_media.c:11838 sofia/websocket/nobody@3PXT9NIJPMV6KC8W skip receive message [BITRATE_REQ] (channel is hungup already) 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_codec.c:248 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Restore previous codec PCMU:0. 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_session.c:2884 sofia/websocket/nobody@3PXT9NIJPMV6KC8W skip receive message [PHONE_EVENT] (channel is hungup already) 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:650 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State EXECUTE going to sleep 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Running State Change CS_HANGUP (Cur 1 Tot 2) 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:850 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Callstate Change ACTIVE -> HANGUP 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:852 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State HANGUP 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] mod_sofia.c:449 Channel sofia/websocket/nobody@3PXT9NIJPMV6KC8W hanging up, cause: NORMAL_UNSPECIFIED 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:60 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Standard HANGUP, cause: NORMAL_UNSPECIFIED 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:852 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State HANGUP going to sleep 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:619 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State Change CS_HANGUP -> CS_REPORTING 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Running State Change CS_REPORTING (Cur 1 Tot 2) 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:938 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State REPORTING 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:174 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Standard REPORTING, cause: NORMAL_UNSPECIFIED 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:938 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State REPORTING going to sleep 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:610 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State Change CS_REPORTING -> CS_DESTROY 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_session.c:1712 Session 2 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Locked, Waiting on external entities 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [NOTICE] switch_core_session.c:1730 Session 2 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Ended 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [NOTICE] switch_core_session.c:1734 Close Channel sofia/websocket/nobody@3PXT9NIJPMV6KC8W [CS_DESTROY] On Fri, May 12, 2017 at 11:51 AM, Luke Wahlmeier <lwahlmeier@gmail.com> wrote: > Thanks Michael, > > I am more then happy to setup something with libks if needed. > > I have figured out some more however. It appears that this only happens > when a wss connections session has not fully established and is cleaning up > because of timing out. The problem is that it causes another wss > connection it to get this ssl error, even if that other wss connection has > a fully established and running audio session. It is important to note it > does not seem to interrupt audio just the wss sip channel, which I am > fairly sure can be reestablished for that audio session w/o an issue. > > The sessions that is being cleaned up sends the logs messages as its doing > it: > 2017-05-12 17:32:46.607768 [NOTICE] sofia.c:8438 Hangup > sofia/websocket/nobody@1LF3F6I924P9WH6U [CS_EXECUTE] [NORMAL_UNSPECIFIED] > 2017-05-12 17:32:46.627768 [INFO] conference_loop.c:1621 Channel leaving > conference, cause: NORMAL_UNSPECIFIED > 2017-05-12 17:32:46.627768 [NOTICE] switch_core_session.c:1730 Session 46 > (sofia/websocket/nobody@1LF3F6I924P9WH6U) Ended > 2017-05-12 17:32:46.627768 [NOTICE] switch_core_session.c:1734 Close > Channel sofia/websocket/nobody@1LF3F6I924P9WH6U [CS_DESTROY] > > I have attached the updated python script, it can duplicate this every > time now with only 2 connections. I verified with a webRTC client that if > I initiate this first connection in the script, let it close, then connect > the webRTC client and get full audio, once the first session from the > script times out it causes the webRTC wss connection to get an error and > close. > > The webRTC connection is in chrome with sip.js. > > Sorry the python script is so nasty, was working through any possible > duplicated sip session stuff in it to make sure that was not why it was > hitting the second connection. > > > On Fri, May 12, 2017 at 10:20 AM, Michael Jerris <mike@jerris.com> wrote: > >> test on master.. work a similar test for verto maybe, this might have to >> do with sip specifically trying to keep state. Might make sense to build >> something out of libks as it has basically the same web socket code, and >> has both client and server web socket support in it, to do a “real” test”, >> instead of this fake sip without any state over web sockets. >> >> >> On May 12, 2017, at 11:42 AM, Luke Wahlmeier <lwahlmeier@gmail.com> >> wrote: >> >> Just got done testing this on v1.6 head and master, both seem to still >> have this issue. This box is using libssl version 1.0.1t-1+deb8u6. I am >> gonna start digging more into the ws/wss/sofia code to see if I can figure >> it out. Any suggestions on debugging this would be appreciated. >> >> Thanks >> Luke >> >> On Thu, May 11, 2017 at 5:12 PM, Luke Wahlmeier <lwahlmeier@gmail.com> >> wrote: >> >>> Its just in our isolated lab, pretty normal dell xeon server running >>> Jessie 8.6. I just want to get it building on the same box I am testing >>> with so setting that all up. >>> >>> I was able to reproduce it w/o DTLS/Srtp. here is a much simpler and >>> cleaned up version of the python script. >>> >>> >>> >>> On Thu, May 11, 2017 at 4:34 PM, Michael Jerris <mike@jerris.com> wrote: >>> >>>> what is “this environment” ? >>>> >>>> On May 11, 2017, at 6:31 PM, Luke Wahlmeier <lwahlmeier@gmail.com> >>>> wrote: >>>> >>>> Yeah I can usually get it to happen within about 5 minutes or so of >>>> testing. Still getting all setup to build freeswitch in this environment, >>>> but I should have it working by tomorrow. I will try more w/o dtls/srtp as >>>> well and make sure it does not need to be on. >>>> >>>> Thanks >>>> Luke >>>> >>>> On Thu, May 11, 2017 at 4:20 PM, Michael Jerris <mike@jerris.com> >>>> wrote: >>>> >>>>> if you can reproduce this reliably, i’d try master as well. Unless >>>>> this is a bug in openssl, i can’t imagine how dtls would come into play in >>>>> something like this. >>>>> >>>>> > On May 11, 2017, at 5:48 PM, Luke Wahlmeier <lwahlmeier@gmail.com> >>>>> wrote: >>>>> > >>>>> > I keep semi-regularly running into issues using the wss transport >>>>> when using dtls/strp/ice. This is on the latest 1.6.17~34~0fc0946 on >>>>> Debian jessie, but I am pretty sure it was happening on the last couple >>>>> releases as well. >>>>> > >>>>> > It seems like something bad/wrong happens to the encrypted data >>>>> going over the websocket coming from freeswitch when more then 1 websocket >>>>> connection are going and so far ice/srtp/dtls also seem to be needed in the >>>>> invite to duplicate it. >>>>> > >>>>> > I have tried many different languages and network/ssl stacks and >>>>> keep running into this. It is always on data coming in from freeswitch on >>>>> the websocket connection, and its very very random. Sometimes I will get >>>>> it 20 times in a row, other times it takes thousands of >>>>> connections/sessions before it happen. It also, obviously, completely goes >>>>> away if I use plain ws instead wss. >>>>> > >>>>> > Here are the errors: >>>>> > python: >>>>> > SSLError: [SSL: DECRYPTION_FAILED_OR_BAD_RECORD_MAC] decryption >>>>> failed or bad record mac (_ssl.c:1750) >>>>> > c/c++ (stunnel4): >>>>> > SSL_read: 1408F119: error:1408F119:SSL routines:SSL3_GET_RECORD:decryption >>>>> failed or bad record mac >>>>> > Java: >>>>> > java.lang.IllegalArgumentException: Bad arguments >>>>> > at javax.crypto.Mac.update(Mac.java:509) >>>>> > at sun.security.ssl.MAC.compute(MAC.java:135) >>>>> > at sun.security.ssl.InputRecord.checkMacTags(InputRecord.java: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@freeswitch.org >>>> http://www.freeswitchsolutions.com >>>> >>>> Official FreeSWITCH Sites >>>> http://www.freeswitch.org >>>> http://confluence.freeswitch.org >>>> http://www.cluecon.com >>>> >>>> FreeSWITCH-users mailing list >>>> FreeSWITCH-users@lists.freeswitch.org >>>> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users >>>> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/free >>>> switch-users >>>> http://www.freeswitch.org >>>> >>> >>> >> _________________________________________________________________________ >> Professional FreeSWITCH Consulting Services: >> consulting@freeswitch.org >> http://www.freeswitchsolutions.com >> >> Official FreeSWITCH Sites >> http://www.freeswitch.org >> http://confluence.freeswitch.org >> http://www.cluecon.com >> >> FreeSWITCH-users mailing list >> FreeSWITCH-users@lists.freeswitch.org >> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users >> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users >> http://www.freeswitch.org >> >> >> >> _________________________________________________________________________ >> Professional FreeSWITCH Consulting Services: >> consulting@freeswitch.org >> http://www.freeswitchsolutions.com >> >> Official FreeSWITCH Sites >> http://www.freeswitch.org >> http://confluence.freeswitch.org >> http://www.cluecon.com >> >> FreeSWITCH-users mailing list >> FreeSWITCH-users@lists.freeswitch.org >> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users >> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users >> http://www.freeswitch.org >> > >
I have been able to verify this is definitely an issue with the sofia wss transport. If I put my own ssl proxy (stunnel) in front and use sofia ws transport the problem goes away. I have tried quite a bit of debugging and cant figure out when/how this is happening, my best guess is something around the ssl locking on connection close, but I have not had the time to dig into that yet. Thanks Luke On Fri, May 12, 2017 at 12:03 PM, Luke Wahlmeier <lwahlmeier@gmail.com> wrote:
Here is the debug logs from this happening:
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [NOTICE] switch_channel.c:1104 New Channel sofia/websocket/nobody@52LX8LP8BBWG6990 [f9a97c98-373b-11e7-9136-499bb33ea37e] f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@52LX8LP8BBWG6990) Running State Change CS_NEW (Cur 1 Tot 1) f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] sofia.c:10028 sofia/websocket/nobody@52LX8LP8BBWG6990 receiving invite from 192.168.56.151:53442 version: 1.9.0 git db24869 2017-05-11 18:22:45Z 64bit f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] sofia.c:11325 Setting NAT mode based on websockets f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] sofia.c:7247 Channel sofia/websocket/nobody@52LX8LP8BBWG6990 entering state [received][100] f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] sofia.c:7257 Remote SDP: f9a97c98-373b-11e7-9136-499bb33ea37e v=0 f9a97c98-373b-11e7-9136-499bb33ea37e o=- 196478633 2 IN IP4 192.168.56.151 f9a97c98-373b-11e7-9136-499bb33ea37e s=- f9a97c98-373b-11e7-9136-499bb33ea37e c=IN IP4 192.168.56.151 f9a97c98-373b-11e7-9136-499bb33ea37e t=0 0 f9a97c98-373b-11e7-9136-499bb33ea37e m=audio 42504 RTP/AVP 0 100 f9a97c98-373b-11e7-9136-499bb33ea37e a=rtpmap:0 PCMU/8000 f9a97c98-373b-11e7-9136-499bb33ea37e a=maxptime:20 f9a97c98-373b-11e7-9136-499bb33ea37e f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[ PCMU:0:8000:20:64000:1] f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_media.c:5165 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [:100:0:20:0:1]/[PCMU:0:8000: 20:64000:1] f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_media.c:3425 Set Codec sofia/websocket/nobody@52LX8LP8BBWG6990 PCMU/8000 20 ms 160 samples 64000 bits 1 channels f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_codec.c:111 sofia/websocket/nobody@52LX8LP8BBWG6990 Original read codec set to PCMU:0 f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_media.c:5398 No 2833 in SDP. Liberal DTMF mode adding 101 as telephone-event. f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_media.c:5427 sofia/websocket/nobody@52LX8LP8BBWG6990 Set 2833 dtmf send payload to 101 recv payload to 101 f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] sofia.c:7670 (sofia/websocket/nobody@52LX8LP8BBWG6990) State Change CS_NEW -> CS_INIT f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_state_machine.c:603 (sofia/websocket/nobody@52LX8LP8BBWG6990) State NEW f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@52LX8LP8BBWG6990) Running State Change CS_INIT (Cur 1 Tot 1) f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_state_machine.c:627 (sofia/websocket/nobody@52LX8LP8BBWG6990) State INIT f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] mod_sofia.c:93 sofia/websocket/nobody@52LX8LP8BBWG6990 SOFIA INIT f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_state_machine.c:40 sofia/websocket/nobody@52LX8LP8BBWG6990 Standard INIT f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:48 (sofia/websocket/nobody@52LX8LP8BBWG6990) State Change CS_INIT -> CS_ROUTING f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:627 (sofia/websocket/nobody@52LX8LP8BBWG6990) State INIT going to sleep f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@52LX8LP8BBWG6990) Running State Change CS_ROUTING (Cur 1 Tot 1) f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_channel.c:2249 (sofia/websocket/nobody@52LX8LP8BBWG6990) Callstate Change DOWN -> RINGING f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:643 (sofia/websocket/nobody@52LX8LP8BBWG6990) State ROUTING f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] mod_sofia.c:154 sofia/websocket/nobody@52LX8LP8BBWG6990 SOFIA ROUTING f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:236 sofia/websocket/nobody@52LX8LP8BBWG6990 Standard ROUTING f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [INFO] mod_dialplan_xml.c:637 Processing unknown <>->52LX8LP8BBWG6990 in context wss-dialplan f9a97c98-373b-11e7-9136-499bb33ea37e Dialplan: sofia/websocket/nobody@52LX8LP8BBWG6990 parsing [wss-dialplan->wss-dialplan] continue=false f9a97c98-373b-11e7-9136-499bb33ea37e Dialplan: sofia/websocket/nobody@52LX8LP8BBWG6990 Regex (PASS) [wss-dialplan] destination_number(52LX8LP8BBWG6990) =~ /.+/ break=on-false f9a97c98-373b-11e7-9136-499bb33ea37e Dialplan: sofia/websocket/nobody@52LX8LP8BBWG6990 Action conference(test123) f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:286 (sofia/websocket/nobody@52LX8LP8BBWG6990) State Change CS_ROUTING -> CS_EXECUTE f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:643 (sofia/websocket/nobody@52LX8LP8BBWG6990) State ROUTING going to sleep f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@52LX8LP8BBWG6990) Running State Change CS_EXECUTE (Cur 1 Tot 1) f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:650 (sofia/websocket/nobody@52LX8LP8BBWG6990) State EXECUTE f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] mod_sofia.c:209 sofia/websocket/nobody@52LX8LP8BBWG6990 SOFIA EXECUTE f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:328 sofia/websocket/nobody@52LX8LP8BBWG6990 Standard EXECUTE f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_session.c:2707 Application conference Requires media! pre_answering channel sofia/websocket/nobody@52LX8LP8BBWG6990 f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [INFO] switch_core_session.c:2709 Sending early media f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_media.c:8144 AUDIO RTP [sofia/websocket/nobody@52LX8LP8BBWG6990] 172.16.19.215 port 27662 -> 192.168.56.151 port 42504 codec: 0 ms: 20 f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_rtp.c:4096 Starting timer [soft] 160 bytes per 20ms f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_media.c:8447 sofia/websocket/nobody@52LX8LP8BBWG6990 Set 2833 dtmf send payload to 101 f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_media.c:8454 sofia/websocket/nobody@52LX8LP8BBWG6990 Set 2833 dtmf receive payload to 101 f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_media.c:8477 sofia/websocket/nobody@52LX8LP8BBWG6990 Set rtp dtmf delay to 40 f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] mod_sofia.c:2512 Ring SDP: f9a97c98-373b-11e7-9136-499bb33ea37e v=0 f9a97c98-373b-11e7-9136-499bb33ea37e o=FreeSWITCH 1494583976 1494583977 IN IP4 172.16.19.215 f9a97c98-373b-11e7-9136-499bb33ea37e s=FreeSWITCH f9a97c98-373b-11e7-9136-499bb33ea37e c=IN IP4 172.16.19.215 f9a97c98-373b-11e7-9136-499bb33ea37e t=0 0 f9a97c98-373b-11e7-9136-499bb33ea37e m=audio 27662 RTP/AVP 0 101 f9a97c98-373b-11e7-9136-499bb33ea37e a=rtpmap:0 PCMU/8000 f9a97c98-373b-11e7-9136-499bb33ea37e a=rtpmap:101 telephone-event/8000 f9a97c98-373b-11e7-9136-499bb33ea37e a=fmtp:101 0-16 f9a97c98-373b-11e7-9136-499bb33ea37e a=ptime:20 f9a97c98-373b-11e7-9136-499bb33ea37e a=sendrecv f9a97c98-373b-11e7-9136-499bb33ea37e f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [NOTICE] mod_sofia.c:2515 Pre-Answer sofia/websocket/nobody@52LX8LP8BBWG6990! f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_channel.c:3481 (sofia/websocket/nobody@52LX8LP8BBWG6990) Callstate Change RINGING -> EARLY f9a97c98-373b-11e7-9136-499bb33ea37e EXECUTE sofia/websocket/nobody@52LX8LP8BBWG6990 conference(test123) f9a97c98-373b-11e7-9136-499bb33ea37e v=0 f9a97c98-373b-11e7-9136-499bb33ea37e o=FreeSWITCH 1494583976 1494583978 IN IP4 172.16.19.215 f9a97c98-373b-11e7-9136-499bb33ea37e s=FreeSWITCH f9a97c98-373b-11e7-9136-499bb33ea37e c=IN IP4 172.16.19.215 f9a97c98-373b-11e7-9136-499bb33ea37e t=0 0 f9a97c98-373b-11e7-9136-499bb33ea37e m=audio 27662 RTP/AVP 0 101 f9a97c98-373b-11e7-9136-499bb33ea37e a=rtpmap:0 PCMU/8000 f9a97c98-373b-11e7-9136-499bb33ea37e a=rtpmap:101 telephone-event/8000 f9a97c98-373b-11e7-9136-499bb33ea37e a=fmtp:101 0-16 f9a97c98-373b-11e7-9136-499bb33ea37e a=ptime:20 f9a97c98-373b-11e7-9136-499bb33ea37e a=sendrecv f9a97c98-373b-11e7-9136-499bb33ea37e f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] sofia.c:7247 Channel sofia/websocket/nobody@52LX8LP8BBWG6990 entering state [early][183] f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [NOTICE] mod_conference.c:1829 Channel [sofia/websocket/nobody@52LX8LP8BBWG6990] has been answered f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_channel.c:3780 (sofia/websocket/nobody@52LX8LP8BBWG6990) Callstate Change EARLY -> ACTIVE f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] sofia.c:7247 Channel sofia/websocket/nobody@52LX8LP8BBWG6990 entering state [completed][200] 2017-05-12 17:53:58.932851 [DEBUG] mod_conference.c:3289 using channel sound prefix: /tmp/fs1.8/share/freeswitch/sounds/en/us/callie f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] conference_member.c:1715 Raw Codec Activation Success L16@8000hz 1 channel 20ms f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] conference_member.c:1762 Raw Codec Activation Success L16@8000hz 1 channel 20ms f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_codec.c:223 sofia/websocket/nobody@52LX8LP8BBWG6990 Push codec L16:100 2017-05-12 17:53:58.932851 [DEBUG] mod_conference.c:227 Setup timer success interval: 20 samples: 160 2017-05-12 17:53:58.932851 [ERR] switch_core_video.c:2868 This function is not available, libpng not installed f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] conference_loop.c:1306 Setup timer soft success interval: 20 samples: 160 from codec PCMU 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [NOTICE] switch_channel.c:1104 New Channel sofia/websocket/nobody@3PXT9NIJPMV6KC8W [02b30be2-373c-11e7-913a-499bb33ea37e] 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Running State Change CS_NEW (Cur 2 Tot 2) 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] sofia.c:10028 sofia/websocket/nobody@3PXT9NIJPMV6KC8W receiving invite from 192.168.56.151:53568 version: 1.9.0 git db24869 2017-05-11 18:22:45Z 64bit 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] sofia.c:11325 Setting NAT mode based on websockets 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] sofia.c:7247 Channel sofia/websocket/nobody@3PXT9NIJPMV6KC8W entering state [received][100] 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] sofia.c:7257 Remote SDP: 02b30be2-373c-11e7-913a-499bb33ea37e v=0 02b30be2-373c-11e7-913a-499bb33ea37e o=- 716582477 2 IN IP4 192.168.56.151 02b30be2-373c-11e7-913a-499bb33ea37e s=- 02b30be2-373c-11e7-913a-499bb33ea37e c=IN IP4 192.168.56.151 02b30be2-373c-11e7-913a-499bb33ea37e t=0 0 02b30be2-373c-11e7-913a-499bb33ea37e m=audio 11866 RTP/AVP 0 100 02b30be2-373c-11e7-913a-499bb33ea37e a=rtpmap:0 PCMU/8000 02b30be2-373c-11e7-913a-499bb33ea37e a=maxptime:20 02b30be2-373c-11e7-913a-499bb33ea37e 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[ PCMU:0:8000:20:64000:1] 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:5165 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [:100:0:20:0:1]/[PCMU:0:8000: 20:64000:1] 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:3425 Set Codec sofia/websocket/nobody@3PXT9NIJPMV6KC8W PCMU/8000 20 ms 160 samples 64000 bits 1 channels 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_codec.c:111 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Original read codec set to PCMU:0 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:5398 No 2833 in SDP. Liberal DTMF mode adding 101 as telephone-event. 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:5427 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Set 2833 dtmf send payload to 101 recv payload to 101 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] sofia.c:7670 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State Change CS_NEW -> CS_INIT 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:603 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State NEW 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Running State Change CS_INIT (Cur 2 Tot 2) 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:627 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State INIT 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] mod_sofia.c:93 sofia/websocket/nobody@3PXT9NIJPMV6KC8W SOFIA INIT 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:40 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Standard INIT 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:48 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State Change CS_INIT -> CS_ROUTING 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:627 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State INIT going to sleep 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Running State Change CS_ROUTING (Cur 2 Tot 2) 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_channel.c:2249 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Callstate Change DOWN -> RINGING 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:643 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State ROUTING 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] mod_sofia.c:154 sofia/websocket/nobody@3PXT9NIJPMV6KC8W SOFIA ROUTING 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:236 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Standard ROUTING 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [INFO] mod_dialplan_xml.c:637 Processing unknown <>->3PXT9NIJPMV6KC8W in context wss-dialplan 02b30be2-373c-11e7-913a-499bb33ea37e Dialplan: sofia/websocket/nobody@3PXT9NIJPMV6KC8W parsing [wss-dialplan->wss-dialplan] continue=false 02b30be2-373c-11e7-913a-499bb33ea37e Dialplan: sofia/websocket/nobody@3PXT9NIJPMV6KC8W Regex (PASS) [wss-dialplan] destination_number(3PXT9NIJPMV6KC8W) =~ /.+/ break=on-false 02b30be2-373c-11e7-913a-499bb33ea37e Dialplan: sofia/websocket/nobody@3PXT9NIJPMV6KC8W Action conference(test123) 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:286 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State Change CS_ROUTING -> CS_EXECUTE 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:643 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State ROUTING going to sleep 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Running State Change CS_EXECUTE (Cur 2 Tot 2) 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:650 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State EXECUTE 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] mod_sofia.c:209 sofia/websocket/nobody@3PXT9NIJPMV6KC8W SOFIA EXECUTE 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:328 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Standard EXECUTE 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_session.c:2707 Application conference Requires media! pre_answering channel sofia/websocket/nobody@3PXT9NIJPMV6KC8W 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [INFO] switch_core_session.c:2709 Sending early media 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:8144 AUDIO RTP [sofia/websocket/nobody@3PXT9NIJPMV6KC8W] 172.16.19.215 port 28858 -> 192.168.56.151 port 11866 codec: 0 ms: 20 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_rtp.c:4096 Starting timer [soft] 160 bytes per 20ms 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:8447 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Set 2833 dtmf send payload to 101 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:8454 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Set 2833 dtmf receive payload to 101 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:8477 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Set rtp dtmf delay to 40 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] mod_sofia.c:2512 Ring SDP: 02b30be2-373c-11e7-913a-499bb33ea37e v=0 02b30be2-373c-11e7-913a-499bb33ea37e o=FreeSWITCH 1494582796 1494582797 IN IP4 172.16.19.215 02b30be2-373c-11e7-913a-499bb33ea37e s=FreeSWITCH 02b30be2-373c-11e7-913a-499bb33ea37e c=IN IP4 172.16.19.215 02b30be2-373c-11e7-913a-499bb33ea37e t=0 0 02b30be2-373c-11e7-913a-499bb33ea37e m=audio 28858 RTP/AVP 0 101 02b30be2-373c-11e7-913a-499bb33ea37e a=rtpmap:0 PCMU/8000 02b30be2-373c-11e7-913a-499bb33ea37e a=rtpmap:101 telephone-event/8000 02b30be2-373c-11e7-913a-499bb33ea37e a=fmtp:101 0-16 02b30be2-373c-11e7-913a-499bb33ea37e a=ptime:20 02b30be2-373c-11e7-913a-499bb33ea37e a=sendrecv 02b30be2-373c-11e7-913a-499bb33ea37e 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [NOTICE] mod_sofia.c:2515 Pre-Answer sofia/websocket/nobody@3PXT9NIJPMV6KC8W! 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_channel.c:3481 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Callstate Change RINGING -> EARLY 02b30be2-373c-11e7-913a-499bb33ea37e EXECUTE sofia/websocket/nobody@3PXT9NIJPMV6KC8W conference(test123) 02b30be2-373c-11e7-913a-499bb33ea37e v=0 02b30be2-373c-11e7-913a-499bb33ea37e o=FreeSWITCH 1494582796 1494582798 IN IP4 172.16.19.215 02b30be2-373c-11e7-913a-499bb33ea37e s=FreeSWITCH 02b30be2-373c-11e7-913a-499bb33ea37e c=IN IP4 172.16.19.215 02b30be2-373c-11e7-913a-499bb33ea37e t=0 0 02b30be2-373c-11e7-913a-499bb33ea37e m=audio 28858 RTP/AVP 0 101 02b30be2-373c-11e7-913a-499bb33ea37e a=rtpmap:0 PCMU/8000 02b30be2-373c-11e7-913a-499bb33ea37e a=rtpmap:101 telephone-event/8000 02b30be2-373c-11e7-913a-499bb33ea37e a=fmtp:101 0-16 02b30be2-373c-11e7-913a-499bb33ea37e a=ptime:20 02b30be2-373c-11e7-913a-499bb33ea37e a=sendrecv 02b30be2-373c-11e7-913a-499bb33ea37e 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] sofia.c:7247 Channel sofia/websocket/nobody@3PXT9NIJPMV6KC8W entering state [early][183] 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [NOTICE] mod_conference.c:1829 Channel [sofia/websocket/nobody@3PXT9NIJPMV6KC8W] has been answered 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_channel.c:3780 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Callstate Change EARLY -> ACTIVE 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] sofia.c:7247 Channel sofia/websocket/nobody@3PXT9NIJPMV6KC8W entering state [completed][200] 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] conference_member.c:1715 Raw Codec Activation Success L16@8000hz 1 channel 20ms 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] conference_member.c:1762 Raw Codec Activation Success L16@8000hz 1 channel 20ms 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_codec.c:223 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Push codec L16:100 2017-05-12 17:54:14.092839 [ERR] switch_core_video.c:2868 This function is not available, libpng not installed 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] conference_loop.c:1306 Setup timer soft success interval: 20 samples: 160 from codec PCMU
This is where session 02b30be2-373c-11e7-913a-499bb33ea37e wss socket gets an ssl errror: f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.952843 [DEBUG] sofia.c:7247 Channel sofia/websocket/nobody@52LX8LP8BBWG6990 entering state [terminating][0] f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.952843 [NOTICE] sofia.c:8438 Hangup sofia/websocket/nobody@52LX8LP8BBWG6990 [CS_EXECUTE] [NORMAL_UNSPECIFIED] f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [INFO] conference_loop.c:1621 Channel leaving conference, cause: NORMAL_UNSPECIFIED f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] mod_conference.c:2404 sofia/websocket/nobody@52LX8LP8BBWG6990 skip receive message [TRANSFER] (channel is hungup already) f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_media.c:11838 sofia/websocket/nobody@52LX8LP8BBWG6990 skip receive message [BITRATE_REQ] (channel is hungup already) f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_codec.c:248 sofia/websocket/nobody@52LX8LP8BBWG6990 Restore previous codec PCMU:0. f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_session.c:2884 sofia/websocket/nobody@52LX8LP8BBWG6990 skip receive message [PHONE_EVENT] (channel is hungup already) f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:650 (sofia/websocket/nobody@52LX8LP8BBWG6990) State EXECUTE going to sleep f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@52LX8LP8BBWG6990) Running State Change CS_HANGUP (Cur 2 Tot 2) f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:850 (sofia/websocket/nobody@52LX8LP8BBWG6990) Callstate Change ACTIVE -> HANGUP f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:852 (sofia/websocket/nobody@52LX8LP8BBWG6990) State HANGUP f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] mod_sofia.c:449 Channel sofia/websocket/nobody@52LX8LP8BBWG6990 hanging up, cause: NORMAL_UNSPECIFIED f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:60 sofia/websocket/nobody@52LX8LP8BBWG6990 Standard HANGUP, cause: NORMAL_UNSPECIFIED f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:852 (sofia/websocket/nobody@52LX8LP8BBWG6990) State HANGUP going to sleep f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:619 (sofia/websocket/nobody@52LX8LP8BBWG6990) State Change CS_HANGUP -> CS_REPORTING f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@52LX8LP8BBWG6990) Running State Change CS_REPORTING (Cur 2 Tot 2) f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:938 (sofia/websocket/nobody@52LX8LP8BBWG6990) State REPORTING f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:174 sofia/websocket/nobody@52LX8LP8BBWG6990 Standard REPORTING, cause: NORMAL_UNSPECIFIED f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:938 (sofia/websocket/nobody@52LX8LP8BBWG6990) State REPORTING going to sleep f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:610 (sofia/websocket/nobody@52LX8LP8BBWG6990) State Change CS_REPORTING -> CS_DESTROY f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_session.c:1712 Session 1 (sofia/websocket/nobody@52LX8LP8BBWG6990) Locked, Waiting on external entities f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [NOTICE] switch_core_session.c:1730 Session 1 (sofia/websocket/nobody@52LX8LP8BBWG6990) Ended f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [NOTICE] switch_core_session.c:1734 Close Channel sofia/websocket/nobody@52LX8LP8BBWG6990 [CS_DESTROY] f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:741 (sofia/websocket/nobody@52LX8LP8BBWG6990) Running State Change CS_DESTROY (Cur 1 Tot 2) f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:751 (sofia/websocket/nobody@52LX8LP8BBWG6990) State DESTROY f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] mod_sofia.c:354 sofia/websocket/nobody@52LX8LP8BBWG6990 SOFIA DESTROY f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:181 sofia/websocket/nobody@52LX8LP8BBWG6990 Standard DESTROY f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:751 (sofia/websocket/nobody@52LX8LP8BBWG6990) State DESTROY going to sleep 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.112842 [DEBUG] sofia.c:7247 Channel sofia/websocket/nobody@3PXT9NIJPMV6KC8W entering state [terminating][0] 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.112842 [NOTICE] sofia.c:8438 Hangup sofia/websocket/nobody@3PXT9NIJPMV6KC8W [CS_EXECUTE] [NORMAL_UNSPECIFIED] 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [INFO] conference_loop.c:1621 Channel leaving conference, cause: NORMAL_UNSPECIFIED 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] mod_conference.c:2404 sofia/websocket/nobody@3PXT9NIJPMV6KC8W skip receive message [TRANSFER] (channel is hungup already) 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_media.c:11838 sofia/websocket/nobody@3PXT9NIJPMV6KC8W skip receive message [BITRATE_REQ] (channel is hungup already) 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_codec.c:248 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Restore previous codec PCMU:0. 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_session.c:2884 sofia/websocket/nobody@3PXT9NIJPMV6KC8W skip receive message [PHONE_EVENT] (channel is hungup already) 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:650 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State EXECUTE going to sleep 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Running State Change CS_HANGUP (Cur 1 Tot 2) 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:850 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Callstate Change ACTIVE -> HANGUP 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:852 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State HANGUP 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] mod_sofia.c:449 Channel sofia/websocket/nobody@3PXT9NIJPMV6KC8W hanging up, cause: NORMAL_UNSPECIFIED 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:60 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Standard HANGUP, cause: NORMAL_UNSPECIFIED 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:852 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State HANGUP going to sleep 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:619 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State Change CS_HANGUP -> CS_REPORTING 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Running State Change CS_REPORTING (Cur 1 Tot 2) 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:938 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State REPORTING 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:174 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Standard REPORTING, cause: NORMAL_UNSPECIFIED 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:938 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State REPORTING going to sleep 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:610 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State Change CS_REPORTING -> CS_DESTROY 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_session.c:1712 Session 2 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Locked, Waiting on external entities 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [NOTICE] switch_core_session.c:1730 Session 2 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Ended 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [NOTICE] switch_core_session.c:1734 Close Channel sofia/websocket/nobody@3PXT9NIJPMV6KC8W [CS_DESTROY]
On Fri, May 12, 2017 at 11:51 AM, Luke Wahlmeier <lwahlmeier@gmail.com> wrote:
Thanks Michael,
I am more then happy to setup something with libks if needed.
I have figured out some more however. It appears that this only happens when a wss connections session has not fully established and is cleaning up because of timing out. The problem is that it causes another wss connection it to get this ssl error, even if that other wss connection has a fully established and running audio session. It is important to note it does not seem to interrupt audio just the wss sip channel, which I am fairly sure can be reestablished for that audio session w/o an issue.
The sessions that is being cleaned up sends the logs messages as its doing it: 2017-05-12 17:32:46.607768 [NOTICE] sofia.c:8438 Hangup sofia/websocket/nobody@1LF3F6I924P9WH6U [CS_EXECUTE] [NORMAL_UNSPECIFIED] 2017-05-12 17:32:46.627768 [INFO] conference_loop.c:1621 Channel leaving conference, cause: NORMAL_UNSPECIFIED 2017-05-12 17:32:46.627768 [NOTICE] switch_core_session.c:1730 Session 46 (sofia/websocket/nobody@1LF3F6I924P9WH6U) Ended 2017-05-12 17:32:46.627768 [NOTICE] switch_core_session.c:1734 Close Channel sofia/websocket/nobody@1LF3F6I924P9WH6U [CS_DESTROY]
I have attached the updated python script, it can duplicate this every time now with only 2 connections. I verified with a webRTC client that if I initiate this first connection in the script, let it close, then connect the webRTC client and get full audio, once the first session from the script times out it causes the webRTC wss connection to get an error and close.
The webRTC connection is in chrome with sip.js.
Sorry the python script is so nasty, was working through any possible duplicated sip session stuff in it to make sure that was not why it was hitting the second connection.
On Fri, May 12, 2017 at 10:20 AM, Michael Jerris <mike@jerris.com> wrote:
test on master.. work a similar test for verto maybe, this might have to do with sip specifically trying to keep state. Might make sense to build something out of libks as it has basically the same web socket code, and has both client and server web socket support in it, to do a “real” test”, instead of this fake sip without any state over web sockets.
On May 12, 2017, at 11:42 AM, Luke Wahlmeier <lwahlmeier@gmail.com> wrote:
Just got done testing this on v1.6 head and master, both seem to still have this issue. This box is using libssl version 1.0.1t-1+deb8u6. I am gonna start digging more into the ws/wss/sofia code to see if I can figure it out. Any suggestions on debugging this would be appreciated.
Thanks Luke
On Thu, May 11, 2017 at 5:12 PM, Luke Wahlmeier <lwahlmeier@gmail.com> wrote:
Its just in our isolated lab, pretty normal dell xeon server running Jessie 8.6. I just want to get it building on the same box I am testing with so setting that all up.
I was able to reproduce it w/o DTLS/Srtp. here is a much simpler and cleaned up version of the python script.
On Thu, May 11, 2017 at 4:34 PM, Michael Jerris <mike@jerris.com> wrote:
what is “this environment” ?
On May 11, 2017, at 6:31 PM, Luke Wahlmeier <lwahlmeier@gmail.com> wrote:
Yeah I can usually get it to happen within about 5 minutes or so of testing. Still getting all setup to build freeswitch in this environment, but I should have it working by tomorrow. I will try more w/o dtls/srtp as well and make sure it does not need to be on.
Thanks Luke
On Thu, May 11, 2017 at 4:20 PM, Michael Jerris <mike@jerris.com> wrote:
if you can reproduce this reliably, i’d try master as well. Unless this is a bug in openssl, i can’t imagine how dtls would come into play in something like this.
> On May 11, 2017, at 5:48 PM, Luke Wahlmeier <lwahlmeier@gmail.com> wrote: > > I keep semi-regularly running into issues using the wss transport when using dtls/strp/ice. This is on the latest 1.6.17~34~0fc0946 on Debian jessie, but I am pretty sure it was happening on the last couple releases as well. > > It seems like something bad/wrong happens to the encrypted data going over the websocket coming from freeswitch when more then 1 websocket connection are going and so far ice/srtp/dtls also seem to be needed in the invite to duplicate it. > > I have tried many different languages and network/ssl stacks and keep running into this. It is always on data coming in from freeswitch on the websocket connection, and its very very random. Sometimes I will get it 20 times in a row, other times it takes thousands of connections/sessions before it happen. It also, obviously, completely goes away if I use plain ws instead wss. > > Here are the errors: > python: > SSLError: [SSL: DECRYPTION_FAILED_OR_BAD_RECORD_MAC] decryption failed or bad record mac (_ssl.c:1750) > c/c++ (stunnel4): > SSL_read: 1408F119: error:1408F119:SSL routines:SSL3_GET_RECORD:decryption failed or bad record mac > Java: > java.lang.IllegalArgumentException: Bad arguments > at javax.crypto.Mac.update(Mac.java:509) > at sun.security.ssl.MAC.compute(MAC.java:135) > at sun.security.ssl.InputRecord.checkMacTags(InputRecord.java: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@freeswitch.org http://www.freeswitchsolutions.com
Official FreeSWITCH Sites http://www.freeswitch.org http://confluence.freeswitch.org http://www.cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/free switch-users http://www.freeswitch.org
____________________________________________________________ _____________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
Official FreeSWITCH Sites http://www.freeswitch.org http://confluence.freeswitch.org http://www.cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
____________________________________________________________ _____________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
Official FreeSWITCH Sites http://www.freeswitch.org http://confluence.freeswitch.org http://www.cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
Please do not post logs into email bodies, people use mobile devices to browse this list. Please do no report issues on this list, its a discussion list. We have a Bug tracker specifically for issues. I forgot completely about this thread because its impossible to mentally remember every one of the email threads in a busy mailing list. https://jira.freeswitch.org This has all you need to attach your data and file a proper report. Otherwise its pure Chaos..... On Thu, May 18, 2017 at 12:34 PM, Luke Wahlmeier <lwahlmeier@gmail.com> wrote:
I have been able to verify this is definitely an issue with the sofia wss transport. If I put my own ssl proxy (stunnel) in front and use sofia ws transport the problem goes away.
I have tried quite a bit of debugging and cant figure out when/how this is happening, my best guess is something around the ssl locking on connection close, but I have not had the time to dig into that yet.
Thanks Luke
On Fri, May 12, 2017 at 12:03 PM, Luke Wahlmeier <lwahlmeier@gmail.com> wrote:
Here is the debug logs from this happening:
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [NOTICE] switch_channel.c:1104 New Channel sofia/websocket/nobody@52LX8LP8BBWG6990 [f9a97c98-373b-11e7-9136-499bb33ea37e] f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@52LX8LP8BBWG6990) Running State Change CS_NEW (Cur 1 Tot 1) f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] sofia.c:10028 sofia/websocket/nobody@52LX8LP8BBWG6990 receiving invite from 192.168.56.151:53442 version: 1.9.0 git db24869 2017-05-11 18:22:45Z 64bit f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] sofia.c:11325 Setting NAT mode based on websockets f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] sofia.c:7247 Channel sofia/websocket/nobody@52LX8LP8BBWG6990 entering state [received][100] f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] sofia.c:7257 Remote SDP: f9a97c98-373b-11e7-9136-499bb33ea37e v=0 f9a97c98-373b-11e7-9136-499bb33ea37e o=- 196478633 2 IN IP4 192.168.56.151 f9a97c98-373b-11e7-9136-499bb33ea37e s=- f9a97c98-373b-11e7-9136-499bb33ea37e c=IN IP4 192.168.56.151 f9a97c98-373b-11e7-9136-499bb33ea37e t=0 0 f9a97c98-373b-11e7-9136-499bb33ea37e m=audio 42504 RTP/AVP 0 100 f9a97c98-373b-11e7-9136-499bb33ea37e a=rtpmap:0 PCMU/8000 f9a97c98-373b-11e7-9136-499bb33ea37e a=maxptime:20 f9a97c98-373b-11e7-9136-499bb33ea37e f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU :0:8000:20:64000:1] f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_media.c:5165 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [:100:0:20:0:1]/[PCMU:0:8000: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@52LX8LP8BBWG6990 PCMU/8000 20 ms 160 samples 64000 bits 1 channels f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_codec.c:111 sofia/websocket/nobody@52LX8LP8BBWG6990 Original read codec set to PCMU:0 f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_media.c:5398 No 2833 in SDP. Liberal DTMF mode adding 101 as telephone-event. f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_media.c:5427 sofia/websocket/nobody@52LX8LP8BBWG6990 Set 2833 dtmf send payload to 101 recv payload to 101 f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] sofia.c:7670 (sofia/websocket/nobody@52LX8LP8BBWG6990) State Change CS_NEW -> CS_INIT f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_state_machine.c:603 (sofia/websocket/nobody@52LX8LP8BBWG6990) State NEW f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@52LX8LP8BBWG6990) Running State Change CS_INIT (Cur 1 Tot 1) f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_state_machine.c:627 (sofia/websocket/nobody@52LX8LP8BBWG6990) State INIT f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] mod_sofia.c:93 sofia/websocket/nobody@52LX8LP8BBWG6990 SOFIA INIT f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_state_machine.c:40 sofia/websocket/nobody@52LX8LP8BBWG6990 Standard INIT f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:48 (sofia/websocket/nobody@52LX8LP8BBWG6990) State Change CS_INIT -> CS_ROUTING f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:627 (sofia/websocket/nobody@52LX8LP8BBWG6990) State INIT going to sleep f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@52LX8LP8BBWG6990) Running State Change CS_ROUTING (Cur 1 Tot 1) f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_channel.c:2249 (sofia/websocket/nobody@52LX8LP8BBWG6990) Callstate Change DOWN -> RINGING f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:643 (sofia/websocket/nobody@52LX8LP8BBWG6990) State ROUTING f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] mod_sofia.c:154 sofia/websocket/nobody@52LX8LP8BBWG6990 SOFIA ROUTING f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:236 sofia/websocket/nobody@52LX8LP8BBWG6990 Standard ROUTING f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [INFO] mod_dialplan_xml.c:637 Processing unknown <>->52LX8LP8BBWG6990 in context wss-dialplan f9a97c98-373b-11e7-9136-499bb33ea37e Dialplan: sofia/websocket/nobody@52LX8LP8BBWG6990 parsing [wss-dialplan->wss-dialplan] continue=false f9a97c98-373b-11e7-9136-499bb33ea37e Dialplan: sofia/websocket/nobody@52LX8LP8BBWG6990 Regex (PASS) [wss-dialplan] destination_number(52LX8LP8BBWG6990) =~ /.+/ break=on-false f9a97c98-373b-11e7-9136-499bb33ea37e Dialplan: sofia/websocket/nobody@52LX8LP8BBWG6990 Action conference(test123) f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:286 (sofia/websocket/nobody@52LX8LP8BBWG6990) State Change CS_ROUTING -> CS_EXECUTE f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:643 (sofia/websocket/nobody@52LX8LP8BBWG6990) State ROUTING going to sleep f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@52LX8LP8BBWG6990) Running State Change CS_EXECUTE (Cur 1 Tot 1) f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:650 (sofia/websocket/nobody@52LX8LP8BBWG6990) State EXECUTE f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] mod_sofia.c:209 sofia/websocket/nobody@52LX8LP8BBWG6990 SOFIA EXECUTE f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:328 sofia/websocket/nobody@52LX8LP8BBWG6990 Standard EXECUTE f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_session.c:2707 Application conference Requires media! pre_answering channel sofia/websocket/nobody@52LX8LP8BBWG6990 f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [INFO] switch_core_session.c:2709 Sending early media f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_media.c:8144 AUDIO RTP [sofia/websocket/nobody@52LX8LP8BBWG6990] 172.16.19.215 port 27662 -> 192.168.56.151 port 42504 codec: 0 ms: 20 f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_rtp.c:4096 Starting timer [soft] 160 bytes per 20ms f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_media.c:8447 sofia/websocket/nobody@52LX8LP8BBWG6990 Set 2833 dtmf send payload to 101 f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_media.c:8454 sofia/websocket/nobody@52LX8LP8BBWG6990 Set 2833 dtmf receive payload to 101 f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_media.c:8477 sofia/websocket/nobody@52LX8LP8BBWG6990 Set rtp dtmf delay to 40 f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] mod_sofia.c:2512 Ring SDP: f9a97c98-373b-11e7-9136-499bb33ea37e v=0 f9a97c98-373b-11e7-9136-499bb33ea37e o=FreeSWITCH 1494583976 1494583977 IN IP4 172.16.19.215 f9a97c98-373b-11e7-9136-499bb33ea37e s=FreeSWITCH f9a97c98-373b-11e7-9136-499bb33ea37e c=IN IP4 172.16.19.215 f9a97c98-373b-11e7-9136-499bb33ea37e t=0 0 f9a97c98-373b-11e7-9136-499bb33ea37e m=audio 27662 RTP/AVP 0 101 f9a97c98-373b-11e7-9136-499bb33ea37e a=rtpmap:0 PCMU/8000 f9a97c98-373b-11e7-9136-499bb33ea37e a=rtpmap:101 telephone-event/8000 f9a97c98-373b-11e7-9136-499bb33ea37e a=fmtp:101 0-16 f9a97c98-373b-11e7-9136-499bb33ea37e a=ptime:20 f9a97c98-373b-11e7-9136-499bb33ea37e a=sendrecv f9a97c98-373b-11e7-9136-499bb33ea37e f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [NOTICE] mod_sofia.c:2515 Pre-Answer sofia/websocket/nobody@52LX8LP8BBWG6990! f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_channel.c:3481 (sofia/websocket/nobody@52LX8LP8BBWG6990) Callstate Change RINGING -> EARLY f9a97c98-373b-11e7-9136-499bb33ea37e EXECUTE sofia/websocket/nobody@52LX8LP8BBWG6990 conference(test123) f9a97c98-373b-11e7-9136-499bb33ea37e v=0 f9a97c98-373b-11e7-9136-499bb33ea37e o=FreeSWITCH 1494583976 1494583978 IN IP4 172.16.19.215 f9a97c98-373b-11e7-9136-499bb33ea37e s=FreeSWITCH f9a97c98-373b-11e7-9136-499bb33ea37e c=IN IP4 172.16.19.215 f9a97c98-373b-11e7-9136-499bb33ea37e t=0 0 f9a97c98-373b-11e7-9136-499bb33ea37e m=audio 27662 RTP/AVP 0 101 f9a97c98-373b-11e7-9136-499bb33ea37e a=rtpmap:0 PCMU/8000 f9a97c98-373b-11e7-9136-499bb33ea37e a=rtpmap:101 telephone-event/8000 f9a97c98-373b-11e7-9136-499bb33ea37e a=fmtp:101 0-16 f9a97c98-373b-11e7-9136-499bb33ea37e a=ptime:20 f9a97c98-373b-11e7-9136-499bb33ea37e a=sendrecv f9a97c98-373b-11e7-9136-499bb33ea37e f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] sofia.c:7247 Channel sofia/websocket/nobody@52LX8LP8BBWG6990 entering state [early][183] f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [NOTICE] mod_conference.c:1829 Channel [sofia/websocket/nobody@52LX8LP8BBWG6990] has been answered f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_channel.c:3780 (sofia/websocket/nobody@52LX8LP8BBWG6990) Callstate Change EARLY -> ACTIVE f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] sofia.c:7247 Channel sofia/websocket/nobody@52LX8LP8BBWG6990 entering state [completed][200] 2017-05-12 17:53:58.932851 [DEBUG] mod_conference.c:3289 using channel sound prefix: /tmp/fs1.8/share/freeswitch/sounds/en/us/callie f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] conference_member.c:1715 Raw Codec Activation Success L16@8000hz 1 channel 20ms f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] conference_member.c:1762 Raw Codec Activation Success L16@8000hz 1 channel 20ms f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_codec.c:223 sofia/websocket/nobody@52LX8LP8BBWG6990 Push codec L16:100 2017-05-12 17:53:58.932851 [DEBUG] mod_conference.c:227 Setup timer success interval: 20 samples: 160 2017-05-12 17:53:58.932851 [ERR] switch_core_video.c:2868 This function is not available, libpng not installed f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] conference_loop.c:1306 Setup timer soft success interval: 20 samples: 160 from codec PCMU 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [NOTICE] switch_channel.c:1104 New Channel sofia/websocket/nobody@3PXT9NIJPMV6KC8W [02b30be2-373c-11e7-913a-499bb33ea37e] 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Running State Change CS_NEW (Cur 2 Tot 2) 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] sofia.c:10028 sofia/websocket/nobody@3PXT9NIJPMV6KC8W receiving invite from 192.168.56.151:53568 version: 1.9.0 git db24869 2017-05-11 18:22:45Z 64bit 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] sofia.c:11325 Setting NAT mode based on websockets 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] sofia.c:7247 Channel sofia/websocket/nobody@3PXT9NIJPMV6KC8W entering state [received][100] 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] sofia.c:7257 Remote SDP: 02b30be2-373c-11e7-913a-499bb33ea37e v=0 02b30be2-373c-11e7-913a-499bb33ea37e o=- 716582477 2 IN IP4 192.168.56.151 02b30be2-373c-11e7-913a-499bb33ea37e s=- 02b30be2-373c-11e7-913a-499bb33ea37e c=IN IP4 192.168.56.151 02b30be2-373c-11e7-913a-499bb33ea37e t=0 0 02b30be2-373c-11e7-913a-499bb33ea37e m=audio 11866 RTP/AVP 0 100 02b30be2-373c-11e7-913a-499bb33ea37e a=rtpmap:0 PCMU/8000 02b30be2-373c-11e7-913a-499bb33ea37e a=maxptime:20 02b30be2-373c-11e7-913a-499bb33ea37e 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU :0:8000:20:64000:1] 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:5165 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [:100:0:20:0:1]/[PCMU:0:8000: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@3PXT9NIJPMV6KC8W PCMU/8000 20 ms 160 samples 64000 bits 1 channels 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_codec.c:111 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Original read codec set to PCMU:0 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:5398 No 2833 in SDP. Liberal DTMF mode adding 101 as telephone-event. 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:5427 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Set 2833 dtmf send payload to 101 recv payload to 101 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] sofia.c:7670 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State Change CS_NEW -> CS_INIT 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:603 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State NEW 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Running State Change CS_INIT (Cur 2 Tot 2) 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:627 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State INIT 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] mod_sofia.c:93 sofia/websocket/nobody@3PXT9NIJPMV6KC8W SOFIA INIT 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:40 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Standard INIT 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:48 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State Change CS_INIT -> CS_ROUTING 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:627 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State INIT going to sleep 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Running State Change CS_ROUTING (Cur 2 Tot 2) 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_channel.c:2249 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Callstate Change DOWN -> RINGING 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:643 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State ROUTING 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] mod_sofia.c:154 sofia/websocket/nobody@3PXT9NIJPMV6KC8W SOFIA ROUTING 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:236 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Standard ROUTING 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [INFO] mod_dialplan_xml.c:637 Processing unknown <>->3PXT9NIJPMV6KC8W in context wss-dialplan 02b30be2-373c-11e7-913a-499bb33ea37e Dialplan: sofia/websocket/nobody@3PXT9NIJPMV6KC8W parsing [wss-dialplan->wss-dialplan] continue=false 02b30be2-373c-11e7-913a-499bb33ea37e Dialplan: sofia/websocket/nobody@3PXT9NIJPMV6KC8W Regex (PASS) [wss-dialplan] destination_number(3PXT9NIJPMV6KC8W) =~ /.+/ break=on-false 02b30be2-373c-11e7-913a-499bb33ea37e Dialplan: sofia/websocket/nobody@3PXT9NIJPMV6KC8W Action conference(test123) 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:286 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State Change CS_ROUTING -> CS_EXECUTE 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:643 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State ROUTING going to sleep 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Running State Change CS_EXECUTE (Cur 2 Tot 2) 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:650 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State EXECUTE 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] mod_sofia.c:209 sofia/websocket/nobody@3PXT9NIJPMV6KC8W SOFIA EXECUTE 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:328 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Standard EXECUTE 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_session.c:2707 Application conference Requires media! pre_answering channel sofia/websocket/nobody@3PXT9NIJPMV6KC8W 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [INFO] switch_core_session.c:2709 Sending early media 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:8144 AUDIO RTP [sofia/websocket/nobody@3PXT9NIJPMV6KC8W] 172.16.19.215 port 28858 -> 192.168.56.151 port 11866 codec: 0 ms: 20 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_rtp.c:4096 Starting timer [soft] 160 bytes per 20ms 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:8447 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Set 2833 dtmf send payload to 101 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:8454 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Set 2833 dtmf receive payload to 101 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:8477 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Set rtp dtmf delay to 40 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] mod_sofia.c:2512 Ring SDP: 02b30be2-373c-11e7-913a-499bb33ea37e v=0 02b30be2-373c-11e7-913a-499bb33ea37e o=FreeSWITCH 1494582796 1494582797 IN IP4 172.16.19.215 02b30be2-373c-11e7-913a-499bb33ea37e s=FreeSWITCH 02b30be2-373c-11e7-913a-499bb33ea37e c=IN IP4 172.16.19.215 02b30be2-373c-11e7-913a-499bb33ea37e t=0 0 02b30be2-373c-11e7-913a-499bb33ea37e m=audio 28858 RTP/AVP 0 101 02b30be2-373c-11e7-913a-499bb33ea37e a=rtpmap:0 PCMU/8000 02b30be2-373c-11e7-913a-499bb33ea37e a=rtpmap:101 telephone-event/8000 02b30be2-373c-11e7-913a-499bb33ea37e a=fmtp:101 0-16 02b30be2-373c-11e7-913a-499bb33ea37e a=ptime:20 02b30be2-373c-11e7-913a-499bb33ea37e a=sendrecv 02b30be2-373c-11e7-913a-499bb33ea37e 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [NOTICE] mod_sofia.c:2515 Pre-Answer sofia/websocket/nobody@3PXT9NIJPMV6KC8W! 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_channel.c:3481 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Callstate Change RINGING -> EARLY 02b30be2-373c-11e7-913a-499bb33ea37e EXECUTE sofia/websocket/nobody@3PXT9NIJPMV6KC8W conference(test123) 02b30be2-373c-11e7-913a-499bb33ea37e v=0 02b30be2-373c-11e7-913a-499bb33ea37e o=FreeSWITCH 1494582796 1494582798 IN IP4 172.16.19.215 02b30be2-373c-11e7-913a-499bb33ea37e s=FreeSWITCH 02b30be2-373c-11e7-913a-499bb33ea37e c=IN IP4 172.16.19.215 02b30be2-373c-11e7-913a-499bb33ea37e t=0 0 02b30be2-373c-11e7-913a-499bb33ea37e m=audio 28858 RTP/AVP 0 101 02b30be2-373c-11e7-913a-499bb33ea37e a=rtpmap:0 PCMU/8000 02b30be2-373c-11e7-913a-499bb33ea37e a=rtpmap:101 telephone-event/8000 02b30be2-373c-11e7-913a-499bb33ea37e a=fmtp:101 0-16 02b30be2-373c-11e7-913a-499bb33ea37e a=ptime:20 02b30be2-373c-11e7-913a-499bb33ea37e a=sendrecv 02b30be2-373c-11e7-913a-499bb33ea37e 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] sofia.c:7247 Channel sofia/websocket/nobody@3PXT9NIJPMV6KC8W entering state [early][183] 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [NOTICE] mod_conference.c:1829 Channel [sofia/websocket/nobody@3PXT9NIJPMV6KC8W] has been answered 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_channel.c:3780 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Callstate Change EARLY -> ACTIVE 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] sofia.c:7247 Channel sofia/websocket/nobody@3PXT9NIJPMV6KC8W entering state [completed][200] 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] conference_member.c:1715 Raw Codec Activation Success L16@8000hz 1 channel 20ms 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] conference_member.c:1762 Raw Codec Activation Success L16@8000hz 1 channel 20ms 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_codec.c:223 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Push codec L16:100 2017-05-12 17:54:14.092839 [ERR] switch_core_video.c:2868 This function is not available, libpng not installed 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] conference_loop.c:1306 Setup timer soft success interval: 20 samples: 160 from codec PCMU
This is where session 02b30be2-373c-11e7-913a-499bb33ea37e wss socket gets an ssl errror: f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.952843 [DEBUG] sofia.c:7247 Channel sofia/websocket/nobody@52LX8LP8BBWG6990 entering state [terminating][0] f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.952843 [NOTICE] sofia.c:8438 Hangup sofia/websocket/nobody@52LX8LP8BBWG6990 [CS_EXECUTE] [NORMAL_UNSPECIFIED] f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [INFO] conference_loop.c:1621 Channel leaving conference, cause: NORMAL_UNSPECIFIED f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] mod_conference.c:2404 sofia/websocket/nobody@52LX8LP8BBWG6990 skip receive message [TRANSFER] (channel is hungup already) f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_media.c:11838 sofia/websocket/nobody@52LX8LP8BBWG6990 skip receive message [BITRATE_REQ] (channel is hungup already) f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_codec.c:248 sofia/websocket/nobody@52LX8LP8BBWG6990 Restore previous codec PCMU:0. f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_session.c:2884 sofia/websocket/nobody@52LX8LP8BBWG6990 skip receive message [PHONE_EVENT] (channel is hungup already) f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:650 (sofia/websocket/nobody@52LX8LP8BBWG6990) State EXECUTE going to sleep f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@52LX8LP8BBWG6990) Running State Change CS_HANGUP (Cur 2 Tot 2) f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:850 (sofia/websocket/nobody@52LX8LP8BBWG6990) Callstate Change ACTIVE -> HANGUP f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:852 (sofia/websocket/nobody@52LX8LP8BBWG6990) State HANGUP f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] mod_sofia.c:449 Channel sofia/websocket/nobody@52LX8LP8BBWG6990 hanging up, cause: NORMAL_UNSPECIFIED f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:60 sofia/websocket/nobody@52LX8LP8BBWG6990 Standard HANGUP, cause: NORMAL_UNSPECIFIED f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:852 (sofia/websocket/nobody@52LX8LP8BBWG6990) State HANGUP going to sleep f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:619 (sofia/websocket/nobody@52LX8LP8BBWG6990) State Change CS_HANGUP -> CS_REPORTING f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@52LX8LP8BBWG6990) Running State Change CS_REPORTING (Cur 2 Tot 2) f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:938 (sofia/websocket/nobody@52LX8LP8BBWG6990) State REPORTING f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:174 sofia/websocket/nobody@52LX8LP8BBWG6990 Standard REPORTING, cause: NORMAL_UNSPECIFIED f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:938 (sofia/websocket/nobody@52LX8LP8BBWG6990) State REPORTING going to sleep f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:610 (sofia/websocket/nobody@52LX8LP8BBWG6990) State Change CS_REPORTING -> CS_DESTROY f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_session.c:1712 Session 1 (sofia/websocket/nobody@52LX8LP8BBWG6990) Locked, Waiting on external entities f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [NOTICE] switch_core_session.c:1730 Session 1 (sofia/websocket/nobody@52LX8LP8BBWG6990) Ended f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [NOTICE] switch_core_session.c:1734 Close Channel sofia/websocket/nobody@52LX8LP8BBWG6990 [CS_DESTROY] f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:741 (sofia/websocket/nobody@52LX8LP8BBWG6990) Running State Change CS_DESTROY (Cur 1 Tot 2) f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:751 (sofia/websocket/nobody@52LX8LP8BBWG6990) State DESTROY f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] mod_sofia.c:354 sofia/websocket/nobody@52LX8LP8BBWG6990 SOFIA DESTROY f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:181 sofia/websocket/nobody@52LX8LP8BBWG6990 Standard DESTROY f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:751 (sofia/websocket/nobody@52LX8LP8BBWG6990) State DESTROY going to sleep 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.112842 [DEBUG] sofia.c:7247 Channel sofia/websocket/nobody@3PXT9NIJPMV6KC8W entering state [terminating][0] 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.112842 [NOTICE] sofia.c:8438 Hangup sofia/websocket/nobody@3PXT9NIJPMV6KC8W [CS_EXECUTE] [NORMAL_UNSPECIFIED] 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [INFO] conference_loop.c:1621 Channel leaving conference, cause: NORMAL_UNSPECIFIED 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] mod_conference.c:2404 sofia/websocket/nobody@3PXT9NIJPMV6KC8W skip receive message [TRANSFER] (channel is hungup already) 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_media.c:11838 sofia/websocket/nobody@3PXT9NIJPMV6KC8W skip receive message [BITRATE_REQ] (channel is hungup already) 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_codec.c:248 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Restore previous codec PCMU:0. 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_session.c:2884 sofia/websocket/nobody@3PXT9NIJPMV6KC8W skip receive message [PHONE_EVENT] (channel is hungup already) 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:650 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State EXECUTE going to sleep 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Running State Change CS_HANGUP (Cur 1 Tot 2) 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:850 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Callstate Change ACTIVE -> HANGUP 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:852 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State HANGUP 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] mod_sofia.c:449 Channel sofia/websocket/nobody@3PXT9NIJPMV6KC8W hanging up, cause: NORMAL_UNSPECIFIED 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:60 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Standard HANGUP, cause: NORMAL_UNSPECIFIED 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:852 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State HANGUP going to sleep 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:619 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State Change CS_HANGUP -> CS_REPORTING 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Running State Change CS_REPORTING (Cur 1 Tot 2) 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:938 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State REPORTING 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:174 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Standard REPORTING, cause: NORMAL_UNSPECIFIED 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:938 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State REPORTING going to sleep 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:610 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State Change CS_REPORTING -> CS_DESTROY 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_session.c:1712 Session 2 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Locked, Waiting on external entities 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [NOTICE] switch_core_session.c:1730 Session 2 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Ended 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [NOTICE] switch_core_session.c:1734 Close Channel sofia/websocket/nobody@3PXT9NIJPMV6KC8W [CS_DESTROY]
On Fri, May 12, 2017 at 11:51 AM, Luke Wahlmeier <lwahlmeier@gmail.com> wrote:
Thanks Michael,
I am more then happy to setup something with libks if needed.
I have figured out some more however. It appears that this only happens when a wss connections session has not fully established and is cleaning up because of timing out. The problem is that it causes another wss connection it to get this ssl error, even if that other wss connection has a fully established and running audio session. It is important to note it does not seem to interrupt audio just the wss sip channel, which I am fairly sure can be reestablished for that audio session w/o an issue.
The sessions that is being cleaned up sends the logs messages as its doing it: 2017-05-12 17:32:46.607768 [NOTICE] sofia.c:8438 Hangup sofia/websocket/nobody@1LF3F6I924P9WH6U [CS_EXECUTE] [NORMAL_UNSPECIFIED] 2017-05-12 17:32:46.627768 [INFO] conference_loop.c:1621 Channel leaving conference, cause: NORMAL_UNSPECIFIED 2017-05-12 17:32:46.627768 [NOTICE] switch_core_session.c:1730 Session 46 (sofia/websocket/nobody@1LF3F6I924P9WH6U) Ended 2017-05-12 17:32:46.627768 [NOTICE] switch_core_session.c:1734 Close Channel sofia/websocket/nobody@1LF3F6I924P9WH6U [CS_DESTROY]
I have attached the updated python script, it can duplicate this every time now with only 2 connections. I verified with a webRTC client that if I initiate this first connection in the script, let it close, then connect the webRTC client and get full audio, once the first session from the script times out it causes the webRTC wss connection to get an error and close.
The webRTC connection is in chrome with sip.js.
Sorry the python script is so nasty, was working through any possible duplicated sip session stuff in it to make sure that was not why it was hitting the second connection.
On Fri, May 12, 2017 at 10:20 AM, Michael Jerris <mike@jerris.com> wrote:
test on master.. work a similar test for verto maybe, this might have to do with sip specifically trying to keep state. Might make sense to build something out of libks as it has basically the same web socket code, and has both client and server web socket support in it, to do a “real” test”, instead of this fake sip without any state over web sockets.
On May 12, 2017, at 11:42 AM, Luke Wahlmeier <lwahlmeier@gmail.com> wrote:
Just got done testing this on v1.6 head and master, both seem to still have this issue. This box is using libssl version 1.0.1t-1+deb8u6. I am gonna start digging more into the ws/wss/sofia code to see if I can figure it out. Any suggestions on debugging this would be appreciated.
Thanks Luke
On Thu, May 11, 2017 at 5:12 PM, Luke Wahlmeier <lwahlmeier@gmail.com> wrote:
Its just in our isolated lab, pretty normal dell xeon server running Jessie 8.6. I just want to get it building on the same box I am testing with so setting that all up.
I was able to reproduce it w/o DTLS/Srtp. here is a much simpler and cleaned up version of the python script.
On Thu, May 11, 2017 at 4:34 PM, Michael Jerris <mike@jerris.com> wrote:
what is “this environment” ?
On May 11, 2017, at 6:31 PM, Luke Wahlmeier <lwahlmeier@gmail.com> wrote:
Yeah I can usually get it to happen within about 5 minutes or so of testing. Still getting all setup to build freeswitch in this environment, but I should have it working by tomorrow. I will try more w/o dtls/srtp as well and make sure it does not need to be on.
Thanks Luke
On Thu, May 11, 2017 at 4:20 PM, Michael Jerris <mike@jerris.com> wrote:
> if you can reproduce this reliably, i’d try master as well. Unless > this is a bug in openssl, i can’t imagine how dtls would come into play in > something like this. > > > On May 11, 2017, at 5:48 PM, Luke Wahlmeier <lwahlmeier@gmail.com> > wrote: > > > > I keep semi-regularly running into issues using the wss transport > when using dtls/strp/ice. This is on the latest 1.6.17~34~0fc0946 on > Debian jessie, but I am pretty sure it was happening on the last couple > releases as well. > > > > It seems like something bad/wrong happens to the encrypted data > going over the websocket coming from freeswitch when more then 1 websocket > connection are going and so far ice/srtp/dtls also seem to be needed in the > invite to duplicate it. > > > > I have tried many different languages and network/ssl stacks and > keep running into this. It is always on data coming in from freeswitch on > the websocket connection, and its very very random. Sometimes I will get > it 20 times in a row, other times it takes thousands of > connections/sessions before it happen. It also, obviously, completely goes > away if I use plain ws instead wss. > > > > Here are the errors: > > python: > > SSLError: [SSL: DECRYPTION_FAILED_OR_BAD_RECORD_MAC] decryption > failed or bad record mac (_ssl.c:1750) > > c/c++ (stunnel4): > > SSL_read: 1408F119: error:1408F119:SSL > routines:SSL3_GET_RECORD:decryption failed or bad record mac > > Java: > > java.lang.IllegalArgumentException: Bad arguments > > at javax.crypto.Mac.update(Mac.java:509) > > at sun.security.ssl.MAC.compute(MAC.java:135) > > at sun.security.ssl.InputRecord.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@freeswitch.org http://www.freeswitchsolutions.com
Official FreeSWITCH Sites http://www.freeswitch.org http://confluence.freeswitch.org http://www.cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/free switch-users http://www.freeswitch.org
____________________________________________________________ _____________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
Official FreeSWITCH Sites http://www.freeswitch.org http://confluence.freeswitch.org http://www.cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/free switch-users http://www.freeswitch.org
____________________________________________________________ _____________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
Official FreeSWITCH Sites http://www.freeswitch.org http://confluence.freeswitch.org http://www.cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/free switch-users http://www.freeswitch.org
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
Official FreeSWITCH Sites http://www.freeswitch.org http://confluence.freeswitch.org http://www.cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
-- Anthony Minessale II ♬ @anthmfs ♬ @FreeSWITCH ♬ ☞ 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@conference.freeswitch.org ☎ +19193869900 https://www.youtube.com/watch?v=9XXgW34t40s https://www.youtube.com/watch?v=NLaDpGQuZDA
Will do, thanks On Thu, May 18, 2017 at 12:08 PM, Anthony Minessale < anthony.minessale@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@gmail.com> wrote:
I have been able to verify this is definitely an issue with the sofia wss transport. If I put my own ssl proxy (stunnel) in front and use sofia ws transport the problem goes away.
I have tried quite a bit of debugging and cant figure out when/how this is happening, my best guess is something around the ssl locking on connection close, but I have not had the time to dig into that yet.
Thanks Luke
On Fri, May 12, 2017 at 12:03 PM, Luke Wahlmeier <lwahlmeier@gmail.com> wrote:
Here is the debug logs from this happening:
f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [NOTICE] switch_channel.c:1104 New Channel sofia/websocket/nobody@52LX8LP8BBWG6990 [f9a97c98-373b-11e7-9136-499bb33ea37e] f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@52LX8LP8BBWG6990) Running State Change CS_NEW (Cur 1 Tot 1) f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] sofia.c:10028 sofia/websocket/nobody@52LX8LP8BBWG6990 receiving invite from 192.168.56.151:53442 version: 1.9.0 git db24869 2017-05-11 18:22:45Z 64bit f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] sofia.c:11325 Setting NAT mode based on websockets f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] sofia.c:7247 Channel sofia/websocket/nobody@52LX8LP8BBWG6990 entering state [received][100] f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] sofia.c:7257 Remote SDP: f9a97c98-373b-11e7-9136-499bb33ea37e v=0 f9a97c98-373b-11e7-9136-499bb33ea37e o=- 196478633 2 IN IP4 192.168.56.151 f9a97c98-373b-11e7-9136-499bb33ea37e s=- f9a97c98-373b-11e7-9136-499bb33ea37e c=IN IP4 192.168.56.151 f9a97c98-373b-11e7-9136-499bb33ea37e t=0 0 f9a97c98-373b-11e7-9136-499bb33ea37e m=audio 42504 RTP/AVP 0 100 f9a97c98-373b-11e7-9136-499bb33ea37e a=rtpmap:0 PCMU/8000 f9a97c98-373b-11e7-9136-499bb33ea37e a=maxptime:20 f9a97c98-373b-11e7-9136-499bb33ea37e f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU :0:8000:20:64000:1] f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_media.c:5165 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [:100:0:20:0:1]/[PCMU:0:8000: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@52LX8LP8BBWG6990 PCMU/8000 20 ms 160 samples 64000 bits 1 channels f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_codec.c:111 sofia/websocket/nobody@52LX8LP8BBWG6990 Original read codec set to PCMU:0 f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_media.c:5398 No 2833 in SDP. Liberal DTMF mode adding 101 as telephone-event. f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_media.c:5427 sofia/websocket/nobody@52LX8LP8BBWG6990 Set 2833 dtmf send payload to 101 recv payload to 101 f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] sofia.c:7670 (sofia/websocket/nobody@52LX8LP8BBWG6990) State Change CS_NEW -> CS_INIT f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_state_machine.c:603 (sofia/websocket/nobody@52LX8LP8BBWG6990) State NEW f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@52LX8LP8BBWG6990) Running State Change CS_INIT (Cur 1 Tot 1) f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_state_machine.c:627 (sofia/websocket/nobody@52LX8LP8BBWG6990) State INIT f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] mod_sofia.c:93 sofia/websocket/nobody@52LX8LP8BBWG6990 SOFIA INIT f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.912851 [DEBUG] switch_core_state_machine.c:40 sofia/websocket/nobody@52LX8LP8BBWG6990 Standard INIT f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:48 (sofia/websocket/nobody@52LX8LP8BBWG6990) State Change CS_INIT -> CS_ROUTING f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:627 (sofia/websocket/nobody@52LX8LP8BBWG6990) State INIT going to sleep f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@52LX8LP8BBWG6990) Running State Change CS_ROUTING (Cur 1 Tot 1) f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_channel.c:2249 (sofia/websocket/nobody@52LX8LP8BBWG6990) Callstate Change DOWN -> RINGING f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:643 (sofia/websocket/nobody@52LX8LP8BBWG6990) State ROUTING f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] mod_sofia.c:154 sofia/websocket/nobody@52LX8LP8BBWG6990 SOFIA ROUTING f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:236 sofia/websocket/nobody@52LX8LP8BBWG6990 Standard ROUTING f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [INFO] mod_dialplan_xml.c:637 Processing unknown <>->52LX8LP8BBWG6990 in context wss-dialplan f9a97c98-373b-11e7-9136-499bb33ea37e Dialplan: sofia/websocket/nobody@52LX8LP8BBWG6990 parsing [wss-dialplan->wss-dialplan] continue=false f9a97c98-373b-11e7-9136-499bb33ea37e Dialplan: sofia/websocket/nobody@52LX8LP8BBWG6990 Regex (PASS) [wss-dialplan] destination_number(52LX8LP8BBWG6990) =~ /.+/ break=on-false f9a97c98-373b-11e7-9136-499bb33ea37e Dialplan: sofia/websocket/nobody@52LX8LP8BBWG6990 Action conference(test123) f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:286 (sofia/websocket/nobody@52LX8LP8BBWG6990) State Change CS_ROUTING -> CS_EXECUTE f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:643 (sofia/websocket/nobody@52LX8LP8BBWG6990) State ROUTING going to sleep f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@52LX8LP8BBWG6990) Running State Change CS_EXECUTE (Cur 1 Tot 1) f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:650 (sofia/websocket/nobody@52LX8LP8BBWG6990) State EXECUTE f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] mod_sofia.c:209 sofia/websocket/nobody@52LX8LP8BBWG6990 SOFIA EXECUTE f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_state_machine.c:328 sofia/websocket/nobody@52LX8LP8BBWG6990 Standard EXECUTE f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_session.c:2707 Application conference Requires media! pre_answering channel sofia/websocket/nobody@52LX8LP8BBWG6990 f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [INFO] switch_core_session.c:2709 Sending early media f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_media.c:8144 AUDIO RTP [sofia/websocket/nobody@52LX8LP8BBWG6990] 172.16.19.215 port 27662 -> 192.168.56.151 port 42504 codec: 0 ms: 20 f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_rtp.c:4096 Starting timer [soft] 160 bytes per 20ms f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_media.c:8447 sofia/websocket/nobody@52LX8LP8BBWG6990 Set 2833 dtmf send payload to 101 f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_media.c:8454 sofia/websocket/nobody@52LX8LP8BBWG6990 Set 2833 dtmf receive payload to 101 f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_media.c:8477 sofia/websocket/nobody@52LX8LP8BBWG6990 Set rtp dtmf delay to 40 f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] mod_sofia.c:2512 Ring SDP: f9a97c98-373b-11e7-9136-499bb33ea37e v=0 f9a97c98-373b-11e7-9136-499bb33ea37e o=FreeSWITCH 1494583976 1494583977 IN IP4 172.16.19.215 f9a97c98-373b-11e7-9136-499bb33ea37e s=FreeSWITCH f9a97c98-373b-11e7-9136-499bb33ea37e c=IN IP4 172.16.19.215 f9a97c98-373b-11e7-9136-499bb33ea37e t=0 0 f9a97c98-373b-11e7-9136-499bb33ea37e m=audio 27662 RTP/AVP 0 101 f9a97c98-373b-11e7-9136-499bb33ea37e a=rtpmap:0 PCMU/8000 f9a97c98-373b-11e7-9136-499bb33ea37e a=rtpmap:101 telephone-event/8000 f9a97c98-373b-11e7-9136-499bb33ea37e a=fmtp:101 0-16 f9a97c98-373b-11e7-9136-499bb33ea37e a=ptime:20 f9a97c98-373b-11e7-9136-499bb33ea37e a=sendrecv f9a97c98-373b-11e7-9136-499bb33ea37e f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [NOTICE] mod_sofia.c:2515 Pre-Answer sofia/websocket/nobody@52LX8LP 8BBWG6990! f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_channel.c:3481 (sofia/websocket/nobody@52LX8LP8BBWG6990) Callstate Change RINGING -> EARLY f9a97c98-373b-11e7-9136-499bb33ea37e EXECUTE sofia/websocket/nobody@52LX8LP8BBWG6990 conference(test123) f9a97c98-373b-11e7-9136-499bb33ea37e v=0 f9a97c98-373b-11e7-9136-499bb33ea37e o=FreeSWITCH 1494583976 1494583978 IN IP4 172.16.19.215 f9a97c98-373b-11e7-9136-499bb33ea37e s=FreeSWITCH f9a97c98-373b-11e7-9136-499bb33ea37e c=IN IP4 172.16.19.215 f9a97c98-373b-11e7-9136-499bb33ea37e t=0 0 f9a97c98-373b-11e7-9136-499bb33ea37e m=audio 27662 RTP/AVP 0 101 f9a97c98-373b-11e7-9136-499bb33ea37e a=rtpmap:0 PCMU/8000 f9a97c98-373b-11e7-9136-499bb33ea37e a=rtpmap:101 telephone-event/8000 f9a97c98-373b-11e7-9136-499bb33ea37e a=fmtp:101 0-16 f9a97c98-373b-11e7-9136-499bb33ea37e a=ptime:20 f9a97c98-373b-11e7-9136-499bb33ea37e a=sendrecv f9a97c98-373b-11e7-9136-499bb33ea37e f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] sofia.c:7247 Channel sofia/websocket/nobody@52LX8LP8BBWG6990 entering state [early][183] f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [NOTICE] mod_conference.c:1829 Channel [sofia/websocket/nobody@52LX8LP8BBWG6990] has been answered f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_channel.c:3780 (sofia/websocket/nobody@52LX8LP8BBWG6990) Callstate Change EARLY -> ACTIVE f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] sofia.c:7247 Channel sofia/websocket/nobody@52LX8LP8BBWG6990 entering state [completed][200] 2017-05-12 17:53:58.932851 [DEBUG] mod_conference.c:3289 using channel sound prefix: /tmp/fs1.8/share/freeswitch/sounds/en/us/callie f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] conference_member.c:1715 Raw Codec Activation Success L16@8000hz 1 channel 20ms f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] conference_member.c:1762 Raw Codec Activation Success L16@8000hz 1 channel 20ms f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] switch_core_codec.c:223 sofia/websocket/nobody@52LX8LP8BBWG6990 Push codec L16:100 2017-05-12 17:53:58.932851 [DEBUG] mod_conference.c:227 Setup timer success interval: 20 samples: 160 2017-05-12 17:53:58.932851 [ERR] switch_core_video.c:2868 This function is not available, libpng not installed f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:53:58.932851 [DEBUG] conference_loop.c:1306 Setup timer soft success interval: 20 samples: 160 from codec PCMU 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [NOTICE] switch_channel.c:1104 New Channel sofia/websocket/nobody@3PXT9NIJPMV6KC8W [02b30be2-373c-11e7-913a-499bb33ea37e] 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Running State Change CS_NEW (Cur 2 Tot 2) 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] sofia.c:10028 sofia/websocket/nobody@3PXT9NIJPMV6KC8W receiving invite from 192.168.56.151:53568 version: 1.9.0 git db24869 2017-05-11 18:22:45Z 64bit 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] sofia.c:11325 Setting NAT mode based on websockets 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] sofia.c:7247 Channel sofia/websocket/nobody@3PXT9NIJPMV6KC8W entering state [received][100] 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] sofia.c:7257 Remote SDP: 02b30be2-373c-11e7-913a-499bb33ea37e v=0 02b30be2-373c-11e7-913a-499bb33ea37e o=- 716582477 2 IN IP4 192.168.56.151 02b30be2-373c-11e7-913a-499bb33ea37e s=- 02b30be2-373c-11e7-913a-499bb33ea37e c=IN IP4 192.168.56.151 02b30be2-373c-11e7-913a-499bb33ea37e t=0 0 02b30be2-373c-11e7-913a-499bb33ea37e m=audio 11866 RTP/AVP 0 100 02b30be2-373c-11e7-913a-499bb33ea37e a=rtpmap:0 PCMU/8000 02b30be2-373c-11e7-913a-499bb33ea37e a=maxptime:20 02b30be2-373c-11e7-913a-499bb33ea37e 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU :0:8000:20:64000:1] 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:5165 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [:100:0:20:0:1]/[PCMU:0:8000: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@3PXT9NIJPMV6KC8W PCMU/8000 20 ms 160 samples 64000 bits 1 channels 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_codec.c:111 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Original read codec set to PCMU:0 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:5398 No 2833 in SDP. Liberal DTMF mode adding 101 as telephone-event. 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:5427 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Set 2833 dtmf send payload to 101 recv payload to 101 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] sofia.c:7670 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State Change CS_NEW -> CS_INIT 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:603 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State NEW 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Running State Change CS_INIT (Cur 2 Tot 2) 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:627 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State INIT 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] mod_sofia.c:93 sofia/websocket/nobody@3PXT9NIJPMV6KC8W SOFIA INIT 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:40 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Standard INIT 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:48 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State Change CS_INIT -> CS_ROUTING 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:627 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State INIT going to sleep 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Running State Change CS_ROUTING (Cur 2 Tot 2) 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_channel.c:2249 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Callstate Change DOWN -> RINGING 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:643 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State ROUTING 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] mod_sofia.c:154 sofia/websocket/nobody@3PXT9NIJPMV6KC8W SOFIA ROUTING 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:236 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Standard ROUTING 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [INFO] mod_dialplan_xml.c:637 Processing unknown <>->3PXT9NIJPMV6KC8W in context wss-dialplan 02b30be2-373c-11e7-913a-499bb33ea37e Dialplan: sofia/websocket/nobody@3PXT9NIJPMV6KC8W parsing [wss-dialplan->wss-dialplan] continue=false 02b30be2-373c-11e7-913a-499bb33ea37e Dialplan: sofia/websocket/nobody@3PXT9NIJPMV6KC8W Regex (PASS) [wss-dialplan] destination_number(3PXT9NIJPMV6KC8W) =~ /.+/ break=on-false 02b30be2-373c-11e7-913a-499bb33ea37e Dialplan: sofia/websocket/nobody@3PXT9NIJPMV6KC8W Action conference(test123) 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:286 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State Change CS_ROUTING -> CS_EXECUTE 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:643 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State ROUTING going to sleep 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Running State Change CS_EXECUTE (Cur 2 Tot 2) 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:650 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State EXECUTE 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] mod_sofia.c:209 sofia/websocket/nobody@3PXT9NIJPMV6KC8W SOFIA EXECUTE 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_state_machine.c:328 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Standard EXECUTE 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_session.c:2707 Application conference Requires media! pre_answering channel sofia/websocket/nobody@3PXT9NIJPMV6KC8W 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [INFO] switch_core_session.c:2709 Sending early media 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:8144 AUDIO RTP [sofia/websocket/nobody@3PXT9NIJPMV6KC8W] 172.16.19.215 port 28858 -> 192.168.56.151 port 11866 codec: 0 ms: 20 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_rtp.c:4096 Starting timer [soft] 160 bytes per 20ms 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:8447 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Set 2833 dtmf send payload to 101 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:8454 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Set 2833 dtmf receive payload to 101 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_media.c:8477 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Set rtp dtmf delay to 40 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] mod_sofia.c:2512 Ring SDP: 02b30be2-373c-11e7-913a-499bb33ea37e v=0 02b30be2-373c-11e7-913a-499bb33ea37e o=FreeSWITCH 1494582796 1494582797 IN IP4 172.16.19.215 02b30be2-373c-11e7-913a-499bb33ea37e s=FreeSWITCH 02b30be2-373c-11e7-913a-499bb33ea37e c=IN IP4 172.16.19.215 02b30be2-373c-11e7-913a-499bb33ea37e t=0 0 02b30be2-373c-11e7-913a-499bb33ea37e m=audio 28858 RTP/AVP 0 101 02b30be2-373c-11e7-913a-499bb33ea37e a=rtpmap:0 PCMU/8000 02b30be2-373c-11e7-913a-499bb33ea37e a=rtpmap:101 telephone-event/8000 02b30be2-373c-11e7-913a-499bb33ea37e a=fmtp:101 0-16 02b30be2-373c-11e7-913a-499bb33ea37e a=ptime:20 02b30be2-373c-11e7-913a-499bb33ea37e a=sendrecv 02b30be2-373c-11e7-913a-499bb33ea37e 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [NOTICE] mod_sofia.c:2515 Pre-Answer sofia/websocket/nobody@3PXT9NI JPMV6KC8W! 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_channel.c:3481 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Callstate Change RINGING -> EARLY 02b30be2-373c-11e7-913a-499bb33ea37e EXECUTE sofia/websocket/nobody@3PXT9NIJPMV6KC8W conference(test123) 02b30be2-373c-11e7-913a-499bb33ea37e v=0 02b30be2-373c-11e7-913a-499bb33ea37e o=FreeSWITCH 1494582796 1494582798 IN IP4 172.16.19.215 02b30be2-373c-11e7-913a-499bb33ea37e s=FreeSWITCH 02b30be2-373c-11e7-913a-499bb33ea37e c=IN IP4 172.16.19.215 02b30be2-373c-11e7-913a-499bb33ea37e t=0 0 02b30be2-373c-11e7-913a-499bb33ea37e m=audio 28858 RTP/AVP 0 101 02b30be2-373c-11e7-913a-499bb33ea37e a=rtpmap:0 PCMU/8000 02b30be2-373c-11e7-913a-499bb33ea37e a=rtpmap:101 telephone-event/8000 02b30be2-373c-11e7-913a-499bb33ea37e a=fmtp:101 0-16 02b30be2-373c-11e7-913a-499bb33ea37e a=ptime:20 02b30be2-373c-11e7-913a-499bb33ea37e a=sendrecv 02b30be2-373c-11e7-913a-499bb33ea37e 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] sofia.c:7247 Channel sofia/websocket/nobody@3PXT9NIJPMV6KC8W entering state [early][183] 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [NOTICE] mod_conference.c:1829 Channel [sofia/websocket/nobody@3PXT9NIJPMV6KC8W] has been answered 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_channel.c:3780 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Callstate Change EARLY -> ACTIVE 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] sofia.c:7247 Channel sofia/websocket/nobody@3PXT9NIJPMV6KC8W entering state [completed][200] 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] conference_member.c:1715 Raw Codec Activation Success L16@8000hz 1 channel 20ms 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] conference_member.c:1762 Raw Codec Activation Success L16@8000hz 1 channel 20ms 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] switch_core_codec.c:223 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Push codec L16:100 2017-05-12 17:54:14.092839 [ERR] switch_core_video.c:2868 This function is not available, libpng not installed 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:14.092839 [DEBUG] conference_loop.c:1306 Setup timer soft success interval: 20 samples: 160 from codec PCMU
This is where session 02b30be2-373c-11e7-913a-499bb33ea37e wss socket gets an ssl errror: f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.952843 [DEBUG] sofia.c:7247 Channel sofia/websocket/nobody@52LX8LP8BBWG6990 entering state [terminating][0] f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.952843 [NOTICE] sofia.c:8438 Hangup sofia/websocket/nobody@52LX8LP8BBWG6990 [CS_EXECUTE] [NORMAL_UNSPECIFIED] f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [INFO] conference_loop.c:1621 Channel leaving conference, cause: NORMAL_UNSPECIFIED f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] mod_conference.c:2404 sofia/websocket/nobody@52LX8LP8BBWG6990 skip receive message [TRANSFER] (channel is hungup already) f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_media.c:11838 sofia/websocket/nobody@52LX8LP8BBWG6990 skip receive message [BITRATE_REQ] (channel is hungup already) f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_codec.c:248 sofia/websocket/nobody@52LX8LP8BBWG6990 Restore previous codec PCMU:0. f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_session.c:2884 sofia/websocket/nobody@52LX8LP8BBWG6990 skip receive message [PHONE_EVENT] (channel is hungup already) f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:650 (sofia/websocket/nobody@52LX8LP8BBWG6990) State EXECUTE going to sleep f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@52LX8LP8BBWG6990) Running State Change CS_HANGUP (Cur 2 Tot 2) f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:850 (sofia/websocket/nobody@52LX8LP8BBWG6990) Callstate Change ACTIVE -> HANGUP f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:852 (sofia/websocket/nobody@52LX8LP8BBWG6990) State HANGUP f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] mod_sofia.c:449 Channel sofia/websocket/nobody@52LX8LP8BBWG6990 hanging up, cause: NORMAL_UNSPECIFIED f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:60 sofia/websocket/nobody@52LX8LP8BBWG6990 Standard HANGUP, cause: NORMAL_UNSPECIFIED f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:852 (sofia/websocket/nobody@52LX8LP8BBWG6990) State HANGUP going to sleep f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:619 (sofia/websocket/nobody@52LX8LP8BBWG6990) State Change CS_HANGUP -> CS_REPORTING f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@52LX8LP8BBWG6990) Running State Change CS_REPORTING (Cur 2 Tot 2) f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:938 (sofia/websocket/nobody@52LX8LP8BBWG6990) State REPORTING f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:174 sofia/websocket/nobody@52LX8LP8BBWG6990 Standard REPORTING, cause: NORMAL_UNSPECIFIED f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:938 (sofia/websocket/nobody@52LX8LP8BBWG6990) State REPORTING going to sleep f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:610 (sofia/websocket/nobody@52LX8LP8BBWG6990) State Change CS_REPORTING -> CS_DESTROY f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_session.c:1712 Session 1 (sofia/websocket/nobody@52LX8LP8BBWG6990) Locked, Waiting on external entities f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [NOTICE] switch_core_session.c:1730 Session 1 (sofia/websocket/nobody@52LX8LP8BBWG6990) Ended f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [NOTICE] switch_core_session.c:1734 Close Channel sofia/websocket/nobody@52LX8LP8BBWG6990 [CS_DESTROY] f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:741 (sofia/websocket/nobody@52LX8LP8BBWG6990) Running State Change CS_DESTROY (Cur 1 Tot 2) f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:751 (sofia/websocket/nobody@52LX8LP8BBWG6990) State DESTROY f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] mod_sofia.c:354 sofia/websocket/nobody@52LX8LP8BBWG6990 SOFIA DESTROY f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:181 sofia/websocket/nobody@52LX8LP8BBWG6990 Standard DESTROY f9a97c98-373b-11e7-9136-499bb33ea37e 2017-05-12 17:54:30.972859 [DEBUG] switch_core_state_machine.c:751 (sofia/websocket/nobody@52LX8LP8BBWG6990) State DESTROY going to sleep 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.112842 [DEBUG] sofia.c:7247 Channel sofia/websocket/nobody@3PXT9NIJPMV6KC8W entering state [terminating][0] 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.112842 [NOTICE] sofia.c:8438 Hangup sofia/websocket/nobody@3PXT9NIJPMV6KC8W [CS_EXECUTE] [NORMAL_UNSPECIFIED] 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [INFO] conference_loop.c:1621 Channel leaving conference, cause: NORMAL_UNSPECIFIED 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] mod_conference.c:2404 sofia/websocket/nobody@3PXT9NIJPMV6KC8W skip receive message [TRANSFER] (channel is hungup already) 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_media.c:11838 sofia/websocket/nobody@3PXT9NIJPMV6KC8W skip receive message [BITRATE_REQ] (channel is hungup already) 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_codec.c:248 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Restore previous codec PCMU:0. 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_session.c:2884 sofia/websocket/nobody@3PXT9NIJPMV6KC8W skip receive message [PHONE_EVENT] (channel is hungup already) 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:650 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State EXECUTE going to sleep 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Running State Change CS_HANGUP (Cur 1 Tot 2) 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:850 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Callstate Change ACTIVE -> HANGUP 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:852 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State HANGUP 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] mod_sofia.c:449 Channel sofia/websocket/nobody@3PXT9NIJPMV6KC8W hanging up, cause: NORMAL_UNSPECIFIED 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:60 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Standard HANGUP, cause: NORMAL_UNSPECIFIED 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:852 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State HANGUP going to sleep 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:619 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State Change CS_HANGUP -> CS_REPORTING 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:584 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Running State Change CS_REPORTING (Cur 1 Tot 2) 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:938 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State REPORTING 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:174 sofia/websocket/nobody@3PXT9NIJPMV6KC8W Standard REPORTING, cause: NORMAL_UNSPECIFIED 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:938 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State REPORTING going to sleep 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_state_machine.c:610 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) State Change CS_REPORTING -> CS_DESTROY 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [DEBUG] switch_core_session.c:1712 Session 2 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Locked, Waiting on external entities 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [NOTICE] switch_core_session.c:1730 Session 2 (sofia/websocket/nobody@3PXT9NIJPMV6KC8W) Ended 02b30be2-373c-11e7-913a-499bb33ea37e 2017-05-12 17:54:46.132852 [NOTICE] switch_core_session.c:1734 Close Channel sofia/websocket/nobody@3PXT9NIJPMV6KC8W [CS_DESTROY]
On Fri, May 12, 2017 at 11:51 AM, Luke Wahlmeier <lwahlmeier@gmail.com> wrote:
Thanks Michael,
I am more then happy to setup something with libks if needed.
I have figured out some more however. It appears that this only happens when a wss connections session has not fully established and is cleaning up because of timing out. The problem is that it causes another wss connection it to get this ssl error, even if that other wss connection has a fully established and running audio session. It is important to note it does not seem to interrupt audio just the wss sip channel, which I am fairly sure can be reestablished for that audio session w/o an issue.
The sessions that is being cleaned up sends the logs messages as its doing it: 2017-05-12 17:32:46.607768 [NOTICE] sofia.c:8438 Hangup sofia/websocket/nobody@1LF3F6I924P9WH6U [CS_EXECUTE] [NORMAL_UNSPECIFIED] 2017-05-12 17:32:46.627768 [INFO] conference_loop.c:1621 Channel leaving conference, cause: NORMAL_UNSPECIFIED 2017-05-12 17:32:46.627768 [NOTICE] switch_core_session.c:1730 Session 46 (sofia/websocket/nobody@1LF3F6I924P9WH6U) Ended 2017-05-12 17:32:46.627768 [NOTICE] switch_core_session.c:1734 Close Channel sofia/websocket/nobody@1LF3F6I924P9WH6U [CS_DESTROY]
I have attached the updated python script, it can duplicate this every time now with only 2 connections. I verified with a webRTC client that if I initiate this first connection in the script, let it close, then connect the webRTC client and get full audio, once the first session from the script times out it causes the webRTC wss connection to get an error and close.
The webRTC connection is in chrome with sip.js.
Sorry the python script is so nasty, was working through any possible duplicated sip session stuff in it to make sure that was not why it was hitting the second connection.
On Fri, May 12, 2017 at 10:20 AM, Michael Jerris <mike@jerris.com> wrote:
test on master.. work a similar test for verto maybe, this might have to do with sip specifically trying to keep state. Might make sense to build something out of libks as it has basically the same web socket code, and has both client and server web socket support in it, to do a “real” test”, instead of this fake sip without any state over web sockets.
On May 12, 2017, at 11:42 AM, Luke Wahlmeier <lwahlmeier@gmail.com> wrote:
Just got done testing this on v1.6 head and master, both seem to still have this issue. This box is using libssl version 1.0.1t-1+deb8u6. I am gonna start digging more into the ws/wss/sofia code to see if I can figure it out. Any suggestions on debugging this would be appreciated.
Thanks Luke
On Thu, May 11, 2017 at 5:12 PM, Luke Wahlmeier <lwahlmeier@gmail.com> wrote:
Its just in our isolated lab, pretty normal dell xeon server running Jessie 8.6. I just want to get it building on the same box I am testing with so setting that all up.
I was able to reproduce it w/o DTLS/Srtp. here is a much simpler and cleaned up version of the python script.
On Thu, May 11, 2017 at 4:34 PM, Michael Jerris <mike@jerris.com> wrote:
> what is “this environment” ? > > On May 11, 2017, at 6:31 PM, Luke Wahlmeier <lwahlmeier@gmail.com> > wrote: > > Yeah I can usually get it to happen within about 5 minutes or so of > testing. Still getting all setup to build freeswitch in this environment, > but I should have it working by tomorrow. I will try more w/o dtls/srtp as > well and make sure it does not need to be on. > > Thanks > Luke > > On Thu, May 11, 2017 at 4:20 PM, Michael Jerris <mike@jerris.com> > wrote: > >> if you can reproduce this reliably, i’d try master as well. Unless >> this is a bug in openssl, i can’t imagine how dtls would come into play in >> something like this. >> >> > On May 11, 2017, at 5:48 PM, Luke Wahlmeier <lwahlmeier@gmail.com> >> wrote: >> > >> > I keep semi-regularly running into issues using the wss transport >> when using dtls/strp/ice. This is on the latest 1.6.17~34~0fc0946 on >> Debian jessie, but I am pretty sure it was happening on the last couple >> releases as well. >> > >> > It seems like something bad/wrong happens to the encrypted data >> going over the websocket coming from freeswitch when more then 1 websocket >> connection are going and so far ice/srtp/dtls also seem to be needed in the >> invite to duplicate it. >> > >> > I have tried many different languages and network/ssl stacks and >> keep running into this. It is always on data coming in from freeswitch on >> the websocket connection, and its very very random. Sometimes I will get >> it 20 times in a row, other times it takes thousands of >> connections/sessions before it happen. It also, obviously, completely goes >> away if I use plain ws instead wss. >> > >> > Here are the errors: >> > python: >> > SSLError: [SSL: DECRYPTION_FAILED_OR_BAD_RECORD_MAC] decryption >> failed or bad record mac (_ssl.c:1750) >> > c/c++ (stunnel4): >> > SSL_read: 1408F119: error:1408F119:SSL >> routines:SSL3_GET_RECORD:decryption failed or bad record mac >> > Java: >> > java.lang.IllegalArgumentException: Bad arguments >> > at javax.crypto.Mac.update(Mac.java:509) >> > at sun.security.ssl.MAC.compute(MAC.java:135) >> > at sun.security.ssl.InputRecord.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@freeswitch.org > http://www.freeswitchsolutions.com > > Official FreeSWITCH Sites > http://www.freeswitch.org > http://confluence.freeswitch.org > http://www.cluecon.com > > FreeSWITCH-users mailing list > FreeSWITCH-users@lists.freeswitch.org > http://lists.freeswitch.org/mailman/listinfo/freeswitch-users > UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/free > switch-users > http://www.freeswitch.org >
____________________________________________________________ _____________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
Official FreeSWITCH Sites http://www.freeswitch.org http://confluence.freeswitch.org http://www.cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/free switch-users http://www.freeswitch.org
____________________________________________________________ _____________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
Official FreeSWITCH Sites http://www.freeswitch.org http://confluence.freeswitch.org http://www.cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/free switch-users http://www.freeswitch.org
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
Official FreeSWITCH Sites http://www.freeswitch.org http://confluence.freeswitch.org http://www.cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
-- Anthony Minessale II ♬ @anthmfs ♬ @FreeSWITCH ♬
☞ 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@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@freeswitch.org http://www.freeswitchsolutions.com
Official FreeSWITCH Sites http://www.freeswitch.org http://confluence.freeswitch.org http://www.cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
participants (3)
-
Anthony Minessale
-
Luke Wahlmeier
-
Michael Jerris