[jitsi-dev] ice4j ICE completion mismatch, one way audio


#1

I have updated Lumicall to use the latest ice4j code from the commit

https://github.com/opentelecoms-org/ice4j/commit/1b07fa8608d227b8b42ad0ce26b8799e973f0ce4

On some calls, when ICE completes, the two peers appear to have a
different understanding of which candidates were chosen:

Caller thinks it is sending direct:

I/ConnectivityCheckClient( 1155): IsControlling: true USE-CANDIDATE:true
I/org.ice4j.ice.CheckList( 1155): Selected pair for stream audio.RTP:
192.168.221.194:21000/udp/host -> 192.168.221.166:21000/udp/host (audio.RTP)
I/org.ice4j.ice.CheckList( 1155): Selected pair for stream audio.RTCP:
192.168.221.194:21001/udp/host -> 192.168.221.166:21001/udp/host
(audio.RTCP)

Callee thinks it has to send to the TURN relay:

I/ConnectivityCheckClient(12285): IsControlling: false USE-CANDIDATE:false
I/org.ice4j.ice.CheckList(12285): Selected pair for stream audio.RTP:
192.168.221.166:21000/udp/host -> 195.8.117.59:54070/udp/relay (audio.RTP)
I/org.ice4j.ice.CheckList(12285): Selected pair for stream audio.RTCP:
192.168.221.166:21001/udp/host -> 195.8.117.59:54071/udp/relay (audio.RTCP)

The caller doesn't receive the audio stream that is being sent to the
relay though, so audio is only heard in one direction.

Has anybody else seen this type of thing intermittently with ice4j? It
only happens for some calls.


#2

I looked at this more closely

I used tcpdump on the wifi router to capture all UDP traffic. I notice
that the caller is only sending the USE-CANDIDATE attribute on the
candidates it really wants to use, so the ICE controller logic appears
valid.

I modified the method CandidatePair.setUseCandidateReceived() to print a
stack trace each time it is invoked:

    public void setUseCandidateReceived()
    {
        this.useCandidate = true;
        new Exception().printStackTrace();
    }

and I notice it is getting called 4 or 5 times. Looking at Agent.java,
I was curious about line 1517, as it doesn't appear to check if the
USE-CANDIDATE attribute was really set:

                synchronized(triggerPair)
                {
                    //next time we will see a request it will be
considered as
                    //having USE-CANDIDATE
1517: triggerPair.setUseCandidateReceived();
                }

···

On 12/10/15 12:41, Daniel Pocock wrote:

I have updated Lumicall to use the latest ice4j code from the commit

https://github.com/opentelecoms-org/ice4j/commit/1b07fa8608d227b8b42ad0ce26b8799e973f0ce4

On some calls, when ICE completes, the two peers appear to have a
different understanding of which candidates were chosen:

Caller thinks it is sending direct:

I/ConnectivityCheckClient( 1155): IsControlling: true USE-CANDIDATE:true
I/org.ice4j.ice.CheckList( 1155): Selected pair for stream audio.RTP:
192.168.221.194:21000/udp/host -> 192.168.221.166:21000/udp/host (audio.RTP)
I/org.ice4j.ice.CheckList( 1155): Selected pair for stream audio.RTCP:
192.168.221.194:21001/udp/host -> 192.168.221.166:21001/udp/host
(audio.RTCP)

Callee thinks it has to send to the TURN relay:

I/ConnectivityCheckClient(12285): IsControlling: false USE-CANDIDATE:false
I/org.ice4j.ice.CheckList(12285): Selected pair for stream audio.RTP:
192.168.221.166:21000/udp/host -> 195.8.117.59:54070/udp/relay (audio.RTP)
I/org.ice4j.ice.CheckList(12285): Selected pair for stream audio.RTCP:
192.168.221.166:21001/udp/host -> 195.8.117.59:54071/udp/relay (audio.RTCP)

The caller doesn't receive the audio stream that is being sent to the
relay though, so audio is only heard in one direction.

Has anybody else seen this type of thing intermittently with ice4j? It
only happens for some calls.


#3

Hey Daniel,

···

On 12/10/15 12:57, Daniel Pocock wrote:

On 12/10/15 12:41, Daniel Pocock wrote:

I have updated Lumicall to use the latest ice4j code from the commit

https://github.com/opentelecoms-org/ice4j/commit/1b07fa8608d227b8b42ad0ce26b8799e973f0ce4

On some calls, when ICE completes, the two peers appear to have a
different understanding of which candidates were chosen:

Caller thinks it is sending direct:

I/ConnectivityCheckClient( 1155): IsControlling: true USE-CANDIDATE:true
I/org.ice4j.ice.CheckList( 1155): Selected pair for stream audio.RTP:
192.168.221.194:21000/udp/host -> 192.168.221.166:21000/udp/host (audio.RTP)
I/org.ice4j.ice.CheckList( 1155): Selected pair for stream audio.RTCP:
192.168.221.194:21001/udp/host -> 192.168.221.166:21001/udp/host
(audio.RTCP)

Callee thinks it has to send to the TURN relay:

I/ConnectivityCheckClient(12285): IsControlling: false USE-CANDIDATE:false
I/org.ice4j.ice.CheckList(12285): Selected pair for stream audio.RTP:
192.168.221.166:21000/udp/host -> 195.8.117.59:54070/udp/relay (audio.RTP)
I/org.ice4j.ice.CheckList(12285): Selected pair for stream audio.RTCP:
192.168.221.166:21001/udp/host -> 195.8.117.59:54071/udp/relay (audio.RTCP)

The caller doesn't receive the audio stream that is being sent to the
relay though, so audio is only heard in one direction.

Has anybody else seen this type of thing intermittently with ice4j? It
only happens for some calls.

I looked at this more closely

I used tcpdump on the wifi router to capture all UDP traffic. I notice
that the caller is only sending the USE-CANDIDATE attribute on the
candidates it really wants to use, so the ICE controller logic appears
valid.

I modified the method CandidatePair.setUseCandidateReceived() to print a
stack trace each time it is invoked:

     public void setUseCandidateReceived()
     {
         this.useCandidate = true;
         new Exception().printStackTrace();
     }

and I notice it is getting called 4 or 5 times. Looking at Agent.java,
I was curious about line 1517, as it doesn't appear to check if the
USE-CANDIDATE attribute was really set:

                 synchronized(triggerPair)
                 {
                     //next time we will see a request it will be
considered as
                     //having USE-CANDIDATE
1517: triggerPair.setUseCandidateReceived();
                 }

Well spotted. It looks like this is legacy code for GTALK compatibility still lying around. Can you see if removing this block solves your problem?

Regards,
Boris


#4

I've put my proposed change here:

https://github.com/jitsi/ice4j/pull/34

It appears to resolve the issue for me.

Due to the nature of the issue, it has to be tested with two peers
behind the same NAT. In my case, one peer had a TURN relay and the
other only has access to a STUN server.

Regards,

Daniel

···

On 13/10/15 05:52, Boris Grozev wrote:

Hey Daniel,

On 12/10/15 12:57, Daniel Pocock wrote:

On 12/10/15 12:41, Daniel Pocock wrote:

I have updated Lumicall to use the latest ice4j code from the commit

https://github.com/opentelecoms-org/ice4j/commit/1b07fa8608d227b8b42ad0ce26b8799e973f0ce4

On some calls, when ICE completes, the two peers appear to have a
different understanding of which candidates were chosen:

Caller thinks it is sending direct:

I/ConnectivityCheckClient( 1155): IsControlling: true USE-CANDIDATE:true
I/org.ice4j.ice.CheckList( 1155): Selected pair for stream audio.RTP:
192.168.221.194:21000/udp/host -> 192.168.221.166:21000/udp/host
(audio.RTP)
I/org.ice4j.ice.CheckList( 1155): Selected pair for stream audio.RTCP:
192.168.221.194:21001/udp/host -> 192.168.221.166:21001/udp/host
(audio.RTCP)

Callee thinks it has to send to the TURN relay:

I/ConnectivityCheckClient(12285): IsControlling: false
USE-CANDIDATE:false
I/org.ice4j.ice.CheckList(12285): Selected pair for stream audio.RTP:
192.168.221.166:21000/udp/host -> 195.8.117.59:54070/udp/relay
(audio.RTP)
I/org.ice4j.ice.CheckList(12285): Selected pair for stream audio.RTCP:
192.168.221.166:21001/udp/host -> 195.8.117.59:54071/udp/relay
(audio.RTCP)

The caller doesn't receive the audio stream that is being sent to the
relay though, so audio is only heard in one direction.

Has anybody else seen this type of thing intermittently with ice4j? It
only happens for some calls.

I looked at this more closely

I used tcpdump on the wifi router to capture all UDP traffic. I notice
that the caller is only sending the USE-CANDIDATE attribute on the
candidates it really wants to use, so the ICE controller logic appears
valid.

I modified the method CandidatePair.setUseCandidateReceived() to print a
stack trace each time it is invoked:

     public void setUseCandidateReceived()
     {
         this.useCandidate = true;
         new Exception().printStackTrace();
     }

and I notice it is getting called 4 or 5 times. Looking at Agent.java,
I was curious about line 1517, as it doesn't appear to check if the
USE-CANDIDATE attribute was really set:

                 synchronized(triggerPair)
                 {
                     //next time we will see a request it will be
considered as
                     //having USE-CANDIDATE
1517: triggerPair.setUseCandidateReceived();
                 }

Well spotted. It looks like this is legacy code for GTALK compatibility
still lying around. Can you see if removing this block solves your problem?