Changes between Initial Version and Version 1 of IceNegotiationFailure


Ignore:
Timestamp:
Dec 3, 2007 4:21:11 PM (17 years ago)
Author:
bennylp
Comment:

--

Legend:

Unmodified
Added
Removed
Modified

  • IceNegotiationFailure

    v1 v1  
     1= Troubleshooting ICE Negotiation Failure = 
     2 
     3ICE negotiation may fail because of several reasons, which will be explained below. With pjsua application, ICE negotiation failure will cause pjsua to disconnect the call with call disconnection reason set to 500 "ICE negotiation failed". 
     4 
     5 
     6== How ICE Works == 
     7 
     8The basic principle of ICE is actually very simple: 
     9 - each party gathers candidate addresses to be used to receive media, and encode and send them in the SDP. Below is a sample SDP containing ICE candidates: 
     10{{{ 
     11v=0 
     12o=- 3400859894 3400859894 IN IP4 1.1.1.1 
     13s=pjmedia 
     14c=IN IP4 1.1.1.1 
     15t=0 0 
     16a=X-nat:6 Symmetric 
     17a=ice-ufrag:349219da 
     18a=ice-pwd:50644d54 
     19m=audio 16902 RTP/AVP 103 101 
     20a=rtpmap:103 speex/16000 
     21a=rtpmap:101 telephone-event/8000 
     22a=fmtp:101 0-15 
     23a=candidate:Hc0a80265 1 UDP 1694498815 192.168.2.101 16052 typ host 
     24a=candidate:Sc0a80266 1 UDP 2130706431 1.1.1.1 16902 typ srflx raddr 192.168.2.101 rport 16052 
     25}}} 
     26 - In the SDP above, there is only one media line (the {{{m=}}} line) and one ICE ''component'' in the media line, that is the RTP component, indicated by component id 1 (the number before the keyword "UDP" in the ''candidate'' lines). The second component, the RTCP component, is omited in this article for brevity.  
     27 - The RTP component above in turn has two ''candidates'': one host candidate which corresponds to local interface IP address 192.168.2.101, and another is server reflexive candidate (the one with ''srflx'' keyword) which was acquired by querying STUN server. 
     28 - When media is started and each party has got the SDP of the remote party, they will start procedures called ''ICE connectivity checks'', or ''ICE negotiation''. The ''ICE connectivity check'' is done by ''pairing'' each candidate in local SDP with the candidates found in remote SDP, and perform connectivity check for each pair by sending STUN ''Binding request'' to the remote address in the pair. When this STUN ''Binding Request'' yields a successful response, then the party knows that this pair of local and remote candidates may be used for the media transmission. The remote party will do the same ''pairing'' and ''connectivity checks'' process too. 
     29 - There are two possible outcomes for this process: successful, and failure. ICE negotiation/connectivity check is successful if for each component in each media line, at least one pair can be used for media transmission. This means that a successful STUN ''Binding response'' has been received for the pair. If any of the component has not received successful STUN ''Binding response'', ICE negotiation is considered failed. 
     30 
     31 
     32== Sample Session == 
     33 
     34ICE process can be traced in the log by turning up log verbosity to 5. The ICE events can be seen by looking at '''"icstr"''' letters in the log sender column. Below are sample of ICE logging. 
     35 
     36=== Failed Scenario === 
     37 
     38{{{ 
     39 16:16:46.672  icstr015DB3D0 ICE session created, comp_cnt=1, role is Controlled agent 
     40 16:16:46.672  icstr015DB3D0 Candidate 0 added: comp_id=1, type=Host, foundation=Hc0a80102, addr=192.168.1.2:14210, base=192.168.1.2:14210, prio=0x64ffffff (1694498815) 
     41 16:16:46.672  icstr015DB3D0 Candidate 1 added: comp_id=1, type=Server Reflexive, foundation=Sc0a80102, addr=76.102.231.35:14210, base=192.168.1.2:14210, prio=0x7effffff (2130706431) 
     42 16:16:46.679  icstr015DB3D0 Check 1: [1] 192.168.1.2:14210-->71.166.160.226:16902 pruned (duplicate found) 
     43 16:16:46.679  icstr015DB3D0 Check 2: [1] 192.168.1.2:14210-->192.168.2.101:16052 pruned (duplicate found) 
     44 16:16:46.679  icstr015DB3D0 Checklist created: 
     45 16:16:46.679  icstr015DB3D0  0: [1] 192.168.1.2:14210-->71.166.160.226:16902 (not nominated, state=Frozen) 
     46 16:16:46.679  icstr015DB3D0  1: [1] 192.168.1.2:14210-->192.168.2.101:16052 (not nominated, state=Frozen) 
     47 16:16:46.679  icstr015DB3D0 Starting ICE check.. 
     48 16:16:46.679  icstr015DB3D0 Check 0: [1] 192.168.1.2:14210-->71.166.160.226:16902: state changed from Frozen to Waiting 
     49 16:16:46.679  icstr015DB3D0 Checklist: state changed from Idle to Running 
     50 16:16:46.679  icstr015DB3D0 Starting checklist periodic check 
     51 16:16:46.679  icstr015DB3D0 Sending connectivity check for check 0: [1] 192.168.1.2:14210-->71.166.160.226:16902 
     52 16:16:46.680  icstr015DB3D0 Check 0: [1] 192.168.1.2:14210-->71.166.160.226:16902: state changed from Waiting to In Progress 
     53 16:16:46.701  icstr015DB3D0 Starting checklist periodic check 
     54 16:16:46.701  icstr015DB3D0 Sending connectivity check for check 1: [1] 192.168.1.2:14210-->192.168.2.101:16052 
     55 16:16:46.701  icstr015DB3D0 Check 1: [1] 192.168.1.2:14210-->192.168.2.101:16052: state changed from Frozen to In Progress 
     56 16:16:46.722  icstr015DB3D0 Starting checklist periodic check 
     57 16:16:54.634  icstr015DB3D0 Check 0: [1] 192.168.1.2:14210-->71.166.160.226:16902 (not nominated): connectivity check FAILED: STUN transaction has timed out (PJNATH_ESTUNTIMEDOUT) 
     58 16:16:54.634  icstr015DB3D0 Check 0: [1] 192.168.1.2:14210-->71.166.160.226:16902: state changed from In Progress to Failed 
     59 16:16:54.634  icstr015DB3D0 Check 1: [1] 192.168.1.2:14210-->192.168.2.101:16052 (not nominated): connectivity check FAILED: STUN transaction has timed out (PJNATH_ESTUNTIMEDOUT) 
     60 16:16:54.634  icstr015DB3D0 Check 1: [1] 192.168.1.2:14210-->192.168.2.101:16052: state changed from In Progress to Failed 
     61 16:16:54.634  icstr015DB3D0 ICE process complete, status=All ICE checklists failed (PJNATH_EICEFAILED) 
     62 16:16:54.634  icstr015DB3D0 Valid list 
     63 16:16:54.634  icstr015DB3D0 ICE negotiation failed after 7:955s: All ICE checklists failed (PJNATH_EICEFAILED) 
     64}}} 
     65 
     66 
     67=== Successful Scenario === 
     68 
     69{{{ 
     70 16:01:46.168  icstr00DCB6D8 ICE session created, comp_cnt=2, role is Controlling agent 
     71 16:01:46.168  icstr00DCB6D8 Candidate 0 added: comp_id=1, type=Host, foundation=Hc0a80001, addr=192.168.0.1:4000, base=192.168.0.1:4000, prio=0x64ffffff (1694498815) 
     72 16:01:46.168  icstr00DCB6D8 Candidate 1 added: comp_id=1, type=Host, foundation=Hc0a80001, addr=192.168.131.1:4000, base=192.168.0.1:4000, prio=0x640000ff (1677721855) 
     73 16:01:46.168  icstr00DCB6D8 Candidate 2 added: comp_id=1, type=Host, foundation=Hc0a80001, addr=172.26.2.79:4000, base=192.168.0.1:4000, prio=0x640000ff (1677721855) 
     74 16:01:46.168  icstr00DCB6D8 Candidate 3 added: comp_id=1, type=Server Reflexive, foundation=Sc0a80001, addr=202.152.240.222:42972, base=192.168.0.1:4000, prio=0x7effffff (2130706431) 
     75 16:01:46.168  icstr00DCB6D8 Candidate 4 added: comp_id=2, type=Host, foundation=Hc0a80001, addr=192.168.0.1:4001, base=192.168.0.1:4001, prio=0x64fffffe (1694498814) 
     76 16:01:46.168  icstr00DCB6D8 Candidate 5 added: comp_id=2, type=Host, foundation=Hc0a80001, addr=192.168.131.1:4001, base=192.168.0.1:4001, prio=0x640000fe (1677721854) 
     77 16:01:46.168  icstr00DCB6D8 Candidate 6 added: comp_id=2, type=Host, foundation=Hc0a80001, addr=172.26.2.79:4001, base=192.168.0.1:4001, prio=0x640000fe (1677721854) 
     78 16:01:46.168  icstr00DCB6D8 Candidate 7 added: comp_id=2, type=Server Reflexive, foundation=Sc0a80001, addr=202.152.240.222:42973, base=192.168.0.1:4001, prio=0x7efffffe (2130706430) 
     79 16:01:49.884  icstr00DCB6D8 Check 2: [1] 192.168.0.1:4000-->192.168.0.2:4000 pruned (duplicate found) 
     80 16:01:49.884  icstr00DCB6D8 Check 3: [1] 172.26.2.79:4000-->192.168.0.2:4000 pruned (equal base) 
     81 16:01:49.884  icstr00DCB6D8 Check 3: [1] 192.168.131.1:4000-->192.168.0.2:4000 pruned (equal base) 
     82 16:01:49.884  icstr00DCB6D8 Check 2: [2] 192.168.0.1:4001-->192.168.0.2:4001 pruned (duplicate found) 
     83 16:01:49.884  icstr00DCB6D8 Check 2: [2] 172.26.2.79:4001-->192.168.0.2:4001 pruned (equal base) 
     84 16:01:49.884  icstr00DCB6D8 Check 2: [2] 192.168.131.1:4001-->192.168.0.2:4001 pruned (equal base) 
     85 16:01:49.884  icstr00DCB6D8 Checklist created: 
     86 16:01:49.884  icstr00DCB6D8  0: [1] 192.168.0.1:4000-->192.168.0.2:4000 (not nominated, state=Frozen) 
     87 16:01:49.894  icstr00DCB6D8  1: [2] 192.168.0.1:4001-->192.168.0.2:4001 (not nominated, state=Frozen) 
     88 16:01:49.894  icstr00DCB6D8 Starting ICE check.. 
     89 16:01:49.894  icstr00DCB6D8 Check 0: [1] 192.168.0.1:4000-->192.168.0.2:4000: state changed from Frozen to Waiting 
     90 16:01:49.904  icstr00DCB6D8 Checklist: state changed from Idle to Running 
     91 16:01:49.904  icstr00DCB6D8 Starting checklist periodic check 
     92 16:01:49.904  icstr00DCB6D8 Sending connectivity check for check 0: [1] 192.168.0.1:4000-->192.168.0.2:4000 
     93 16:01:49.904  icstr00DCB6D8 Check 0: [1] 192.168.0.1:4000-->192.168.0.2:4000: state changed from Waiting to In Progress 
     94 16:01:49.924  icstr00DCB6D8 Starting checklist periodic check 
     95 16:01:49.924  icstr00DCB6D8 Sending connectivity check for check 1: [2] 192.168.0.1:4001-->192.168.0.2:4001 
     96 16:01:49.924  icstr00DCB6D8 Check 1: [2] 192.168.0.1:4001-->192.168.0.2:4001: state changed from Frozen to In Progress 
     97 16:01:49.924  icstr00DCB6D8 Check 0: [1] 192.168.0.1:4000-->192.168.0.2:4000 (nominated): connectivity check SUCCESS 
     98 16:01:49.924  icstr00DCB6D8 Check 0: [1] 192.168.0.1:4000-->192.168.0.2:4000: state changed from In Progress to Succeeded 
     99 16:01:49.924  icstr00DCB6D8 Check 0 is successful and nominated 
     100 16:01:49.934  icstr00DCB6D8 Triggered check for check 0 not performed because it's completed 
     101 16:01:49.934  icstr00DCB6D8 Check 0 is successful and nominated 
     102 16:01:49.944  icstr00DCB6D8 Starting checklist periodic check 
     103 16:01:49.954  icstr00DCB6D8 Triggered check for check 1 not performed because it's in progress. Retransmitting 
     104 16:01:49.954  icstr00DCB6D8 Check 1: [2] 192.168.0.1:4001-->192.168.0.2:4001 (nominated): connectivity check SUCCESS 
     105 16:01:49.964  icstr00DCB6D8 Check 1: [2] 192.168.0.1:4001-->192.168.0.2:4001: state changed from In Progress to Succeeded 
     106 16:01:49.964  icstr00DCB6D8 Check 1 is successful and nominated 
     107 16:01:49.964  icstr00DCB6D8 ICE process complete, status=Success 
     108 16:01:49.964  icstr00DCB6D8 Valid list 
     109 16:01:49.964  icstr00DCB6D8  0: [1] 192.168.0.1:4000-->192.168.0.2:4000 (nominated, state=Succeeded) 
     110 16:01:49.964  icstr00DCB6D8  1: [2] 192.168.0.1:4001-->192.168.0.2:4001 (nominated, state=Succeeded) 
     111 16:01:49.974  icstr00DCB6D8 ICE negotiation completed in 0.090s. Sending from 192.168.0.1:4000 to 192.168.0.2:4000 
     112}}} 
     113 
     114 
     115== ICE Negotiation Failures == 
     116 
     117ICE negotiation failure is normally caused by no successful STUN ''Binding response'' is received by the client for any of the candidate pairs. This could be caused by one of the following. 
     118 
     119=== Incompatile Firewall/NAT === 
     120 
     121This is the most common cause of negotiation failure. If one endpoint is behind a symmetric NAT (address and port dependent mapping) and the other is behind another symmetric NAT or an open cone NAT but with address and port dependent filtering capability, then the STUN ''Binding request'' will not reach the destination, and the connectivity check will fail with time out error (PJNATH_ESTUNTIMEDOUT). 
     122 
     123To assist troubleshooting this type of problem, pjsip (pjsua-lib) adds the NAT type information in the SDP content, for example: 
     124{{{ 
     125a=X-nat:6 Symmetric 
     126}}} 
     127 
     128The possible types as classified by pjnath are: 
     129{{{ 
     130  Type    Name 
     131 ----------------------- 
     132   0    Unknown 
     133   1    ErrUnknown 
     134   2    Open 
     135   3    Blocked 
     136   4    Symmetric UDP 
     137   5    Full Cone 
     138   6    Symmetric 
     139   7    Restricted 
     140   8    Port Restricted 
     141}}} 
     142 
     143By examining the NAT types in both local and remote SDPs, one should have a rough idea on the behavior of the NAT in front of each endpoints. However please be warned that NAT type classification should not be considered as a definite type, since some NAT routers are known to change its type based on traffic type and other parameters. This information is provided as additional information only. 
     144 
     145 
     146=== Unreachable IP address === 
     147 
     148It is also possible that the candidates specified in SDP are all unreachable directly from the other endpoint, for example if the candidates all specify private IP addresses. To troubleshoot this problem, check the ''candidate'' lines in the SDP. 
     149 
     150 
     151=== Incompatible STUN Version === 
     152 
     153In rare cases, it may be possible that the STUN version used by the two endpoints are not compatible with one another, for example when either party implements different STUN draft version which happen to be incompatible with the version that the other implements. This could result in various errors, for example the STUN ''Binding request/response'' will not be able to authenticate. 
     154 
     155=== Other Causes === 
     156 
     157The list above are definitely not exhaustive, as there may be other causes of ICE negotiation failures. 
     158