Hi all, I've been experimenting with latest CSipSimple which is based on PJSIP 2.1 and I believe I have found a possible bug in STUN/ICE implementation. I've exchanged emails with the CSip developer but I believe this is a PJSIP issue at core. I'm reproducing the post I sent to the CSip dveloper group instead of writing a new one. Has anyone seen this type of behaviour before? Thanks >From here<https://groups.google.com/forum/#!topic/csipsimple-dev/jygbP5_i8oM> "Hi Re?is, Thanks for your help. Indeed I have been exploring the documentation more thoroughly and I managed to configure the accounts according to your instructions. And it seems I have discovered a bug in the ICE implementation in the process which would explain the strange behaviour I'm seeing. I couldn't figure out why sometimes I couldn't answer calls (pushing the green answer slider has no effect and the call keeps ringing), and a few seconds later the same call worked without problems even though nothing changed. This was baffling me until I looked more closely at the logs. I also found out that if I disable STUN completely, ICE negotiation works very well. The problem with this approach is that it only works when both clients are on the same NATed network since their public IPs never get sent as ice candidates. Obviously that is not a real solution but it does help to point the finger at STUN and ICE not playing well in PJSIP. Here's an excerpt below of the logs for 2 different calls (changed the public IPs to protect the innocent): Notice how we get the error message "ICE process complete, status=All ICE checklists failed (PJNATH_EICEFAILED)" even though ICE connectivity check actually was OK "Check 1: [1] 192.168.1.11:4027-->92.xx.xx.29:4013 (nominated): connectivity check SUCCESS)"? Indeed calling between 2 CSip clients with the same app version and configuration (one of the latest nightlies) shows different results in their logs. One shows ICE negotiation success, while the other shows Failure or negotiation in progress even though there's audio flowing between the 2. This suggests to me a bug with ICE/STUN implementation, no? Do you have any ideas as to the origin of this issue and what to do to fix it ASAP? Thanks Call 1 22:04:21.541 icetp00 !Starting checklist periodic check 22:04:21.541 icetp00 .Sending connectivity check for check 1: [1] 192.168.1.11:4027-->92.xx.xx.29:4013 22:04:21.548 icetp00 ..Check 1: [1] 192.168.1.11:4027-->92.xx.xx.29:4013: state changed from Frozen to In Progress 22:04:21.558 strm0xb5f19c !Error sending RTP: ICE check is in progress (PJNATH_EICEINPROGRESS) 22:04:21.559 strm0xb5f19c Error sending RTP: ICE check is in progress (PJNATH_EICEINPROGRESS) 22:04:21.608 strm0xb5f19c Error sending RTP: ICE check is in progress (PJNATH_EICEINPROGRESS) 22:04:21.609 strm0xb5f19c Error sending RTP: ICE check is in progress (PJNATH_EICEINPROGRESS) 22:04:21.610 strm0xb5f19c Error sending RTP: ICE check is in progress (PJNATH_EICEINPROGRESS) 22:04:21.614 *icetp00 !.Check 1: [1] 192.168.1.11:4027-->92.xx.xx.29:4013 (nominated): connectivity check SUCCESS* 22:04:21.614 icetp00 .Candidate 4 added: comp_id=1, type=prflx, foundation=Pc0a8010b, addr=95.xx.xx.56:1032, base=192.168.1.11:4027, prio=0x7effffff (2130706431) 22:04:21.614 icetp00 .Check 1: [1] 192.168.1.11:4027-->92.xx.xx.29:4013: state changed from In Progress to Succeeded 22:04:21.614 icetp00 .Check 2: [2] 192.168.1.11:4002-->79.xx.xx.34:30450: state changed from Frozen to Waiting 22:04:21.614 icetp00 .Check 3: [2] 192.168.1.11:4002-->92.xx.xx.29:4036: state changed from Frozen to Waiting 22:04:21.614 icetp00 * .Check 1 is successful and nominated* 22:04:21.614 icetp00 .Cancelling check 0: [1] 192.168.1.11:4027-->79.xx.xx.34:30446 (In Progress) 22:04:21.626 icetp00 .Check 0: [1] 192.168.1.11:4027-->79.xx.xx.34:30446: state changed from In Progress to Failed 22:04:21.635 icetp00 .Triggered check for check 1 not performed because it's completed 22:04:21.635 icetp00 ..Check 1 is successful and nominated 22:04:21.639 icetp00 !Starting checklist periodic check 22:04:21.639 icetp00 .Sending connectivity check for check 2: [2] 192.168.1.11:4002-->79.xx.xx.34:30450 22:04:21.646 icetp00 ..Check 2: [2] 192.168.1.11:4002-->79.xx.xx.34:30450: state changed from Waiting to In Progress 22:04:21.693 icetp00 Starting checklist periodic check 22:04:21.693 icetp00 .Sending connectivity check for check 3: [2] 192.168.1.11:4002-->92.xx.xx.29:4036 22:04:21.700 icetp00 ..Check 3: [2] 192.168.1.11:4002-->92.xx.xx.29:4036: state changed from Waiting to In Progress 22:04:21.736 icetp00 Starting checklist periodic check 22:04:21.761 icetp00 !.Triggered check for check 1 not performed because it's completed 22:04:21.761 icetp00 ..Check 1 is successful and nominated 22:04:21.831 icetp00 .Check 3: [2] 192.168.1.11:4002-->92.xx.xx.29:4036 (nominated): connectivity check SUCCESS 22:04:21.831 icetp00 .Check 3: [2] 192.168.1.11:4002-->92.xx.xx.29:4036: state changed from In Progress to Succeeded 22:04:21.831 icetp00 .Check 3 is successful and nominated 22:04:21.831 icetp00 .Cancelling check 2: [2] 192.168.1.11:4002-->79.xx.xx.34:30450 (In Progress) 22:04:21.839 icetp00 .Check 2: [2] 192.168.1.11:4002-->79.xx.xx.34:30450: state changed from In Progress to Failed 22:04:21.839 icetp00 * .ICE process complete, status=All ICE checklists failed (PJNATH_EICEFAILED)* 22:04:21.839 icetp00 .Valid list 22:04:21.839 icetp00 . 0: [1] 95.xx.xx.56:1032-->92.xx.xx.29:4013 (nominated, state=Succeeded) 22:04:21.839 icetp00 . 1: [1] 95.xx.xx.56:1032-->92.xx.xx.29:4036 (nominated, state=Succeeded) 22:04:21.855 icetp00 .Triggered check for check 3 not performed because it's completed 22:04:21.855 icetp00 ..Check 3 is successful and nominated 22:04:21.874 icetp00 !ICE negotiation failed after 0s:600: All ICE checklists failed (PJNATH_EICEFAILED) 22:04:21.899 icetp00 !.Triggered check for check 3 not performed because it's completed 22:04:21.899 icetp00 ..Check 3 is successful and nominated Call 2 22:07:40.239 icetp00 *.Check 1: [1] 192.168.1.11:4000-->92.xx.xx.29:4027 (nominated): connectivity check SUCCESS* 22:07:40.239 icetp00 .Candidate 4 added: comp_id=1, type=prflx, foundation=Pc0a8010b, addr=95.xx.xx.56:1032, base=192.168.1.11:4000, prio=0x7effffff (2130706431) 22:07:40.240 icetp00 .Check 1: [1] 192.168.1.11:4000-->92.xx.xx.29:4027: state changed from In Progress to Succeeded 22:07:40.240 icetp00 .Check 2: [2] 192.168.1.11:4015-->79.xx.xx.34:30474: state changed from Frozen to Waiting 22:07:40.240 icetp00 .Check 3: [2] 192.168.1.11:4015-->92.xx.xx.29:4039: state changed from Frozen to Waiting 22:07:40.240 icetp00 .Check 1 is successful and nominated 22:07:40.240 icetp00 .Cancelling check 0: [1] 192.168.1.11:4000-->79.xx.xx.34:30470 (In Progress) 22:07:40.244 icetp00 .Check 0: [1] 192.168.1.11:4000-->79.xx.xx.34:30470: state changed from In Progress to Failed 22:07:40.274 icetp00 .Triggered check for check 1 not performed because it's completed 22:07:40.274 icetp00 .*.Check 1 is successful and nominated* 22:07:40.280 icetp00 .Triggered check for check 1 not performed because it's completed 22:07:40.281 icetp00 ..Check 1 is successful and nominated 22:07:40.281 pjsua_core.c .RX 1636 bytes Response msg 200/INVITE/cseq=8965 (rdata0xdd3c14) from TLS 79.xx.xx.34:5071: SIP/2.0 200 OK Record-Route: <sip:127.0.0.1:5062 ;lr=on;ftag=TptWgy7WZjiBHrHEskTO7-5CYURWwGYR;did=205.a1e;mpd=ii;ice_caller=add;ice_callee=add;rtpprx=yes;vsf=dm5ucG1uYlUkOSgMfDM2FkoRTGQCBQAfF0UKKw--> Record-Route: <sip:127.0.0.1;r2=on;lr=on;ftag=TptWgy7WZjiBHrHEskTO7-5CYURWwGYR;ngcplb=yes;socket=tls:79.xx.xx.34:5071> Record-Route: <sip:79.xx.xx.34:5071;transport=tls;r2=on;lr=on;ftag=TptWgy7WZjiBHrHEskTO7-5CYURWwGYR;ngcplb=yes;socket=tls:79.xx.xx.34:5071> v: SIP/2.0/TLS 192.168.1.11:56200 ;received=95.xx.xx.56;rport=56200;branch=z9hG4bKPj9U906kDYZBcF4FHsF0VJs4ibd2-hHEPO;alias f: <sip:1004 at mydomain>;tag=TptWgy7WZjiBHrHEskTO7-5CYURWwGYR t: <sip:1000 at mydomain>;tag=528093C0-52951BAB00033401-3224D700 i: 39pK8XtsZtTV6ClEBKD0kIFZ7cWdnLpk CSeq: 8965 INVITE Content-Type: application/sdp Content-Length: 712 Contact: <sip:ngcp-lb at 79.xx.xx.34 :5060;ngcpct=7369703a3132372e302e302e313a35303830> v=0 o=- 3594492458 3594492459 IN IP4 79.xx.xx.34 s=pjmedia c=IN IP4 79.xx.xx.34 t=0 0 m=audio 30470 RTP/AVP 111 101 c=IN IP4 79.xx.xx.34 a=sendrecv a=rtpmap:111 opus/48000/2 a=fmtp:111 maxcodedaudiobandwidth=16000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=zrtp-hash:1.10 1771024f5885b9fbb1797988724afa85e3baf1ac647c8818c65ac625dfb59cb9 a=ice-ufrag:576a214f a=ice-pwd:6f687e8a a=candidate:H5cfa0f37 1 UDP 2130706431 92.xx.xx.29 4027 typ host a=candidate:H5cfa0f37 2 UDP 2130706430 92.xx.xx.29 4039 typ host a=rtcp:30474 a=candidate:52aORdqRksCtzDKU 1 UDP 2130706432 79.xx.xx.34 30470 typ host a=candidate:52aORdqRksCtzDKU 2 UDP 2130706431 79.xx.xx.34 30474 typ host --end msg-- 22:07:40.281 mobile_reg_han .mod_reg_tracker_on_rx_response 22:07:40.281 mobile_reg_han .mod_reg_tracker_on_rx_response done 22:07:40.282 pjsua_core.c ...TX 820 bytes Request msg ACK/cseq=8965 (tdta0xf29258) to TLS 79.xx.xx.34:5071: ACK sip:ngcp-lb at 79.xx.xx.34:5060;ngcpct=7369703a3132372e302e302e313a35303830 SIP/2.0 v: SIP/2.0/TLS 192.168.1.11:56200 ;rport;branch=z9hG4bKPj97os6Z6WgvyeQhh7OchtrEKWzj4Hd6zX;alias Max-Forwards: 70 f: <sip:1004 at mydomain>;tag=TptWgy7WZjiBHrHEskTO7-5CYURWwGYR t: <sip:1000 at mydomain>;tag=528093C0-52951BAB00033401-3224D700 i: 39pK8XtsZtTV6ClEBKD0kIFZ7cWdnLpk CSeq: 8965 ACK Route: <sip:79.xx.xx.34:5071;transport=tls;lr;r2=on;ftag=TptWgy7WZjiBHrHEskTO7-5CYURWwGYR;ngcplb=yes;socket=tls:79.xx.xx.34:5071> Route: <sip:127.0.0.1;lr;r2=on;ftag=TptWgy7WZjiBHrHEskTO7-5CYURWwGYR;ngcplb=yes;socket=tls:79.xx.xx.34:5071> Route: <sip:127.0.0.1:5062 ;lr;ftag=TptWgy7WZjiBHrHEskTO7-5CYURWwGYR;did=205.a1e;mpd=ii;ice_caller=add;ice_callee=add;rtpprx=yes;vsf=dm5ucG1uYlUkOSgMfDM2FkoRTGQCBQAfF0UKKw--> l: 0 --end msg-- 22:07:40.305 icetp00 !Starting checklist periodic check 22:07:40.305 icetp00 .Sending connectivity check for check 2: [2] 192.168.1.11:4015-->79.xx.xx.34:30474 22:07:40.309 icetp00 ..Check 2: [2] 192.168.1.11:4015-->79.xx.xx.34:30474: state changed from Waiting to In Progress 22:07:40.348 icetp00 Starting checklist periodic check 22:07:40.348 icetp00 .Sending connectivity check for check 3: [2] 192.168.1.11:4015-->92.xx.xx.29:4039 22:07:40.355 icetp00 ..Check 3: [2] 192.168.1.11:4015-->92.xx.xx.29:4039: state changed from Waiting to In Progress 22:07:40.388 icetp00 Starting checklist periodic check 22:07:40.429 icetp00 !.Check 3: [2] 192.168.1.11:4015-->92.xx.xx.29:4039 (nominated): connectivity check SUCCESS 22:07:40.429 icetp00 .Check 3: [2] 192.168.1.11:4015-->92.xx.xx.29:4039: state changed from In Progress to Succeeded 22:07:40.429 icetp00 .Check 3 is successful and nominated 22:07:40.429 icetp00 .Cancelling check 2: [2] 192.168.1.11:4015-->79.xx.xx.34:30474 (In Progress) 22:07:40.441 icetp00 .Check 2: [2] 192.168.1.11:4015-->79.xx.xx.34:30474: state changed from In Progress to Failed 22:07:40.442 icetp00 * .ICE process complete, status=All ICE checklists failed (PJNATH_EICEFAILED)* 22:07:40.442 icetp00 .Valid list 22:07:40.442 icetp00 . 0: [1] 95.xx.xx.56:1032-->92.xx.xx.29:4027 (nominated, state=Succeeded) 22:07:40.442 icetp00 . 1: [1] 95.xx.xx.56:1032-->92.xx.xx.29:4039 (nominated, state=Succeeded) 22:07:40.462 icetp00 .Triggered check for check 3 not performed because it's completed 22:07:40.463 icetp00 ..Check 3 is successful and nominated 22:07:40.481 icetp00 !ICE negotiation failed after 0s:599: All ICE checklists failed (PJNATH_EICEFAILED) 22:07:40.534 pjsua_jni_addo Get secure for media type 1 22:07:40.534 pjsua_aud.c Conf connect: 2 --> 0 22:07:40.534 pjsua_aud.c Conf connect: 0 --> 2 22:07:40.743 zrtp_android.c !ZRTP info message: Hello received, preparing a Commit 22:07:40.760 zrtp_android.c ZRTP info message: Commit: Generated a public DH key 22:07:40.977 zrtp_android.c ZRTP info message: Responder: Commit received, preparing DHPart1 22:07:40.977 zrtp_android.c ZRTP info message: DH1Part: Generated a public DH key 22:07:41.266 zrtp_android.c ZRTP info message: Responder: DHPart2 received, preparing Confirm1 22:07:41.294 zrtp_android.c ZRTP info message: At least one retained secrets matches - security OK 22:07:41.500 ec0xbcc8f8 !Underflow, buf_cnt=3, will generate 1 frame 22:07:41.525 zrtp_android.c !ZRTP info message: Responder: Confirm2 received, preparing Conf2Ack 22:07:41.536 zrtp_android.c Show sas : ya6e in ctxt e7767c 22:07:41.537 zrtp_android.c ZRTP info message: Entered secure state 22:07:41.542 zrtp_android.c ZRTP warning message: Dropping packet because SRTP authentication failed! 22:07:41.542 zrtp_android.c ZRTP warning message: Dropping packet because SRTP authentication failed! 22:07:41.542 pjsua_jni_addo !Get secure for media type 1 22:07:41.543 pjsua_jni_addo ZRTP :: V 1 22:07:41.543 pjsua_jni_addo ZRTP :: S L 4 22:07:41.543 pjsua_jni_addo ZRTP :: C L 16 22:07:41.558 zrtp_android.c !ZRTP warning message: Dropping packet because SRTP authentication failed! 22:07:41.563 pjsua_jni_addo !Get secure for media type 1 22:07:41.563 pjsua_jni_addo ZRTP :: V 1 22:07:41.563 pjsua_jni_addo ZRTP :: S L 4 22:07:41.563 pjsua_jni_addo ZRTP :: C L 16 22:07:41.564 zrtp_android.c !ZRTP warning message: Dropping packet because SRTP authentication failed! 22:07:41.568 pjsua_jni_addo !Get secure for media type 1 22:07:41.568 pjsua_jni_addo ZRTP :: V 1 22:07:41.568 pjsua_jni_addo ZRTP :: S L 4 22:07:41.568 pjsua_jni_addo ZRTP :: C L 16 22:07:41.609 zrtp_android.c !ZRTP warning message: Dropping packet because SRTP authentication failed! 22:07:41.614 zrtp_android.c ZRTP warning message: Dropping packet because SRTP authentication failed! 22:07:41.642 zrtp_android.c ZRTP warning message: Dropping packet because SRTP authentication failed! 22:07:41.681 zrtp_android.c ZRTP warning message: Dropping packet because SRTP authentication failed! 22:07:41.687 zrtp_android.c ZRTP warning message: Dropping packet because SRTP authentication failed! 22:07:41.695 zrtp_android.c ZRTP warning message: Dropping packet because SRTP authentication failed! 22:07:41.708 zrtp_android.c ZRTP warning message: Dropping packet because SRTP authentication failed! 22:07:41.732 zrtp_android.c ZRTP warning message: Dropping packet because SRTP authentication failed! 22:07:48.479 Master/sound !Underflow, buf_cnt=2, will generate 1 frame 22:07:59.141 pjsua_call.c !Call 2 hanging up: code=0.. 22:07:59.142 pjsua_core.c ....TX 861 bytes Request msg BYE/cseq=8966 (tdta0xcc67a8) to TLS 79.xx.xx.34:5071: BYE sip:ngcp-lb at 79.xx.xx.34:5060;ngcpct=7369703a3132372e302e302e313a35303830 SIP/2.0 v: SIP/2.0/TLS 192.168.1.11:56200 ;rport;branch=z9hG4bKPjb6thLuSioAYo2rme0.zoX54UXaAi4muj;alias Max-Forwards: 70 f: <sip:1004 at mydomain>;tag=TptWgy7WZjiBHrHEskTO7-5CYURWwGYR t: <sip:1000 at mydomain>;tag=528093C0-52951BAB00033401-3224D700 i: 39pK8XtsZtTV6ClEBKD0kIFZ7cWdnLpk CSeq: 8966 BYE Route: <sip:79.xx.xx.34:5071;transport=tls;lr;r2=on;ftag=TptWgy7WZjiBHrHEskTO7-5CYURWwGYR;ngcplb=yes;socket=tls:79.xx.xx.34:5071> Route: <sip:127.0.0.1;lr;r2=on;ftag=TptWgy7WZjiBHrHEskTO7-5CYURWwGYR;ngcplb=yes;socket=tls:79.xx.xx.34:5071> Route: <sip:127.0.0.1:5062 ;lr;ftag=TptWgy7WZjiBHrHEskTO7-5CYURWwGYR;did=205.a1e;mpd=ii;ice_caller=add;ice_callee=add;rtpprx=yes;vsf=dm5ucG1uYlUkOSgMfDM2FkoRTGQCBQAfF0UKKw--> User-Agent:Test_ST27i-15/r2328 l: 0" -------------- next part -------------- An HTML attachment was scrubbed... URL: <http://lists.pjsip.org/pipermail/pjsip_lists.pjsip.org/attachments/20131127/05644ca7/attachment-0001.html>
