ZRTP negotiation taking almost 10 seconds every time
Hi, I've been trying to debug why ZRTP negotiation with FS as endpoint takes almost 10 seconds every single time. I remember in the past ZRTP negotiation used to take 2 to 3 seconds at most. I'm calling MoH extension from CSipSimple with ZRTP enabled to test it out and indeed it always takes 9 seconds to negotiate the ZRTP exchange. And even after it does it successfully and enteres secured state, I still see a lot of errors related to failed decryption. I have posted the FS and CSipSimple logs on pastebin. FS log here http://pastebin.com/WNGcpTqB and CSipSimple log here http://pastebin.com/DfW5gqSW These are the relevant excerpts from FS which may help to shed light as to what's going on. You can see that the zrtp hellos from FS apparently never reach the CSipSimple client: *2014-06-10 16:17:55.949864 [DEBUG] switch_rtp.c:1352 [ zrtp engine]: WARNING! HELLO Max retransmissions count reached (20 retries). ID=9* But then you see a five second interval of nothing until CSipSimple's ZRTP hello reaches FS and the negotiation starts: *2014-06-10 16:17:55.949864 [DEBUG] switch_rtp.c:1352 [ zrtp]: Stream ID=9 CLEAR switching <START> ---> <NOZRTP>.* *2014-06-10 16:18:00.789889 [DEBUG] switch_rtp.c:1352 [ zrtp utils]: Received <Hello > packet with ssrc=0 seq=1/1 size=168. Stream9:CLEAR:NOZRTP.* Once that's successfull indeed ZRTP appears to work properly, although I still see a lot of errors like this: 2*014-06-10 16:18:01.509898 [DEBUG] switch_rtp.c:1352 [zrtp protoco]: ERROR! Decrypt failed. ID=9:DH s=SRTP authentication failure (RTP size=51 ssrc=690666908 seq=20192/20192 pt=111)* *2014-06-10 16:18:01.509898 [DEBUG] switch_rtp.c:1352 [ zrtp engine]: Add 140 bytes of entropy to the RNG pool.* Now I guess this could be due to dropped packets, but I'm curious if others have seen the same thing in their setups. Also, I see this message in the FS logs. On the CS logs everything seems to be fine. Why does FS think that CS needs new un-enrolment? I presume that nedpint is actually a typo for endpoint, but this just made me more confused. *2014-06-10 16:18:01.769867 [DEBUG] switch_rtp.c:1352 [zrtp protoco]: INFO! The user requires new un-enrolment - the nedpint may clear the cache or perform other action. ID=9* *c60c4480-f0ba-11e3-aa6e-ddba267b1226 2014-06-10 16:18:01.769867 [DEBUG] switch_rtp.c:1323 User unenrolled!* *2014-06-10 16:18:01.769867 [DEBUG] switch_rtp.c:1352 [ zrtp cache]: cache_put() zid1=346638366666393864366363, zis2=3888449c219de624b44b3ece MiTM=NO* *2014-06-10 16:18:01.769867 [DEBUG] switch_rtp.c:1352 [ zrtp cache]: cache_put() Just update existing value.* Any ideas as to what's happening? Thanks
Answering myself since I seem to have finally figured it out. Hopefully this will save others the time I've spent debugging this. The delay happens because ICE in FS is not responding correctly to CSipSimple's stun binding requests, which eventually timeout. If I turn off ICE in CSipSimple, then ZRTP negotiation happens almost instantly as it should. I believe there's an issue with FS's ICE implementation. Others seem to have noticed the same problem (see http://lists.freeswitch.org/pipermail/freeswitch-users/2014-June/105877.html ) Is it possible to tweak and/or turn off ICE in FS? Thanks On Tue, Jun 10, 2014 at 6:23 PM, Peter Villeneuve <petervnv1@gmail.com> wrote:
Hi,
I've been trying to debug why ZRTP negotiation with FS as endpoint takes almost 10 seconds every single time. I remember in the past ZRTP negotiation used to take 2 to 3 seconds at most.
I'm calling MoH extension from CSipSimple with ZRTP enabled to test it out and indeed it always takes 9 seconds to negotiate the ZRTP exchange. And even after it does it successfully and enteres secured state, I still see a lot of errors related to failed decryption.
I have posted the FS and CSipSimple logs on pastebin. FS log here http://pastebin.com/WNGcpTqB and CSipSimple log here http://pastebin.com/DfW5gqSW
These are the relevant excerpts from FS which may help to shed light as to what's going on. You can see that the zrtp hellos from FS apparently never reach the CSipSimple client:
*2014-06-10 16:17:55.949864 [DEBUG] switch_rtp.c:1352 [ zrtp engine]: WARNING! HELLO Max retransmissions count reached (20 retries). ID=9*
But then you see a five second interval of nothing until CSipSimple's ZRTP hello reaches FS and the negotiation starts:
*2014-06-10 16:17:55.949864 [DEBUG] switch_rtp.c:1352 [ zrtp]: Stream ID=9 CLEAR switching <START> ---> <NOZRTP>.* *2014-06-10 16:18:00.789889 [DEBUG] switch_rtp.c:1352 [ zrtp utils]: Received <Hello > packet with ssrc=0 seq=1/1 size=168. Stream9:CLEAR:NOZRTP.*
Once that's successfull indeed ZRTP appears to work properly, although I still see a lot of errors like this:
2*014-06-10 16:18:01.509898 [DEBUG] switch_rtp.c:1352 [zrtp protoco]: ERROR! Decrypt failed. ID=9:DH s=SRTP authentication failure (RTP size=51 ssrc=690666908 seq=20192/20192 pt=111)* *2014-06-10 16:18:01.509898 [DEBUG] switch_rtp.c:1352 [ zrtp engine]: Add 140 bytes of entropy to the RNG pool.*
Now I guess this could be due to dropped packets, but I'm curious if others have seen the same thing in their setups. Also, I see this message in the FS logs. On the CS logs everything seems to be fine. Why does FS think that CS needs new un-enrolment? I presume that nedpint is actually a typo for endpoint, but this just made me more confused.
*2014-06-10 16:18:01.769867 [DEBUG] switch_rtp.c:1352 [zrtp protoco]: INFO! The user requires new un-enrolment - the nedpint may clear the cache or perform other action. ID=9* *c60c4480-f0ba-11e3-aa6e-ddba267b1226 2014-06-10 16:18:01.769867 [DEBUG] switch_rtp.c:1323 User unenrolled!* *2014-06-10 16:18:01.769867 [DEBUG] switch_rtp.c:1352 [ zrtp cache]: cache_put() zid1=346638366666393864366363, zis2=3888449c219de624b44b3ece MiTM=NO* *2014-06-10 16:18:01.769867 [DEBUG] switch_rtp.c:1352 [ zrtp cache]: cache_put() Just update existing value.*
Any ideas as to what's happening?
Thanks
Thanks for the follow up. I never really understood how ICE works and consider it broken by default. Even though i have a ton of css's with ice and stun and p2p zrtp enrollment happens instantly or as soon as rtp appears. On Jun 10, 2014 10:39 PM, "Peter Villeneuve" <petervnv1@gmail.com> wrote:
Answering myself since I seem to have finally figured it out. Hopefully this will save others the time I've spent debugging this.
The delay happens because ICE in FS is not responding correctly to CSipSimple's stun binding requests, which eventually timeout. If I turn off ICE in CSipSimple, then ZRTP negotiation happens almost instantly as it should.
I believe there's an issue with FS's ICE implementation. Others seem to have noticed the same problem (see http://lists.freeswitch.org/pipermail/freeswitch-users/2014-June/105877.html )
Is it possible to tweak and/or turn off ICE in FS?
Thanks
On Tue, Jun 10, 2014 at 6:23 PM, Peter Villeneuve <petervnv1@gmail.com> wrote:
Hi,
I've been trying to debug why ZRTP negotiation with FS as endpoint takes almost 10 seconds every single time. I remember in the past ZRTP negotiation used to take 2 to 3 seconds at most.
I'm calling MoH extension from CSipSimple with ZRTP enabled to test it out and indeed it always takes 9 seconds to negotiate the ZRTP exchange. And even after it does it successfully and enteres secured state, I still see a lot of errors related to failed decryption.
I have posted the FS and CSipSimple logs on pastebin. FS log here http://pastebin.com/WNGcpTqB and CSipSimple log here http://pastebin.com/DfW5gqSW
These are the relevant excerpts from FS which may help to shed light as to what's going on. You can see that the zrtp hellos from FS apparently never reach the CSipSimple client:
*2014-06-10 16:17:55.949864 [DEBUG] switch_rtp.c:1352 [ zrtp engine]: WARNING! HELLO Max retransmissions count reached (20 retries). ID=9*
But then you see a five second interval of nothing until CSipSimple's ZRTP hello reaches FS and the negotiation starts:
*2014-06-10 16:17:55.949864 [DEBUG] switch_rtp.c:1352 [ zrtp]: Stream ID=9 CLEAR switching <START> ---> <NOZRTP>.* *2014-06-10 16:18:00.789889 [DEBUG] switch_rtp.c:1352 [ zrtp utils]: Received <Hello > packet with ssrc=0 seq=1/1 size=168. Stream9:CLEAR:NOZRTP.*
Once that's successfull indeed ZRTP appears to work properly, although I still see a lot of errors like this:
2*014-06-10 16:18:01.509898 [DEBUG] switch_rtp.c:1352 [zrtp protoco]: ERROR! Decrypt failed. ID=9:DH s=SRTP authentication failure (RTP size=51 ssrc=690666908 seq=20192/20192 pt=111)* *2014-06-10 16:18:01.509898 [DEBUG] switch_rtp.c:1352 [ zrtp engine]: Add 140 bytes of entropy to the RNG pool.*
Now I guess this could be due to dropped packets, but I'm curious if others have seen the same thing in their setups. Also, I see this message in the FS logs. On the CS logs everything seems to be fine. Why does FS think that CS needs new un-enrolment? I presume that nedpint is actually a typo for endpoint, but this just made me more confused.
*2014-06-10 16:18:01.769867 [DEBUG] switch_rtp.c:1352 [zrtp protoco]: INFO! The user requires new un-enrolment - the nedpint may clear the cache or perform other action. ID=9* *c60c4480-f0ba-11e3-aa6e-ddba267b1226 2014-06-10 16:18:01.769867 [DEBUG] switch_rtp.c:1323 User unenrolled!* *2014-06-10 16:18:01.769867 [DEBUG] switch_rtp.c:1352 [ zrtp cache]: cache_put() zid1=346638366666393864366363, zis2=3888449c219de624b44b3ece MiTM=NO* *2014-06-10 16:18:01.769867 [DEBUG] switch_rtp.c:1352 [ zrtp cache]: cache_put() Just update existing value.*
Any ideas as to what's happening?
Thanks
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.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
File a JIRA! Sent from my iPad
On Jun 10, 2014, at 3:36 PM, Peter Villeneuve <petervnv1@gmail.com> wrote:
I believe there's an issue with FS's ICE implementation. Others seem to have noticed the same problem (see http://lists.freeswitch.org/pipermail/freeswitch-users/2014-June/105877.html)
Is it possible to tweak and/or turn off ICE in FS?
Thanks
I would, but I'm about to leave on a week long trip, and besides, the OP from the other thread will probably do it. If nothing's changed when I get back I'll go ahead and file it. On Tue, Jun 10, 2014 at 10:24 PM, Brian West <brian@freeswitch.org> wrote:
File a JIRA!
Sent from my iPad
On Jun 10, 2014, at 3:36 PM, Peter Villeneuve <petervnv1@gmail.com> wrote:
I believe there's an issue with FS's ICE implementation. Others seem to have noticed the same problem (see http://lists.freeswitch.org/pipermail/freeswitch-users/2014-June/105877.html )
Is it possible to tweak and/or turn off ICE in FS?
Thanks
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.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
Finally filed the Jira since the OP from the other thread apparently didn't. Please take a look at FS-6628 On Tue, Jun 10, 2014 at 10:31 PM, Peter Villeneuve <petervnv1@gmail.com> wrote:
I would, but I'm about to leave on a week long trip, and besides, the OP from the other thread will probably do it. If nothing's changed when I get back I'll go ahead and file it.
On Tue, Jun 10, 2014 at 10:24 PM, Brian West <brian@freeswitch.org> wrote:
File a JIRA!
Sent from my iPad
On Jun 10, 2014, at 3:36 PM, Peter Villeneuve <petervnv1@gmail.com> wrote:
I believe there's an issue with FS's ICE implementation. Others seem to have noticed the same problem (see http://lists.freeswitch.org/pipermail/freeswitch-users/2014-June/105877.html )
Is it possible to tweak and/or turn off ICE in FS?
Thanks
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.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)
-
Brian West
-
Daniel Ivanov
-
Peter Villeneuve