[Freeswitch-users] ZRTP negotiation taking almost 10 seconds every time

[Peter Villeneuve]

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
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20140610/2db2cf7b/attachment.html