Anyone have any input? Has anyone experienced the same behaviour at all? According to http://trac.pjsip.org/repos/wiki/IceNegotiationFailure this behaviour should not happen (ie a successfull connection check should not lead to PJNATH_EICEFAILED). This is what leads me to believe this is a bug. Thanks On Wed, Nov 27, 2013 at 1:10 PM, Privus 007 <privus007 at gmail.com> wrote: > 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/20131128/c99b95d1/attachment-0001.html>
