ice4j 3.0 cannot support video content-add when initial call starts with audio only

cmeng-git commented 2 years ago

In an audio call only session, adding the video (content-add) is not working.

Please refer to ConnectivityCheckClient.java source: After an audio call setup is completed, Agent proceeds to execute ConnectivityCheckClient#stop(), setting the flag stopped = true; When a video content-add is initiated, startChecks() does not proceed due to stopped == true. This is fixed with the following source changed.

    /**
     * Starts client connectivity checks for the first {@link IceMediaStream}
     * in our parent {@link Agent}. This method should only be called by
     * the parent {@link Agent} when connectivity establishment starts for a
     * particular check list.
     */
    public void startChecks()
    {
        List<IceMediaStream> streamsWithPendingConnectivityEstablishment
                = parentAgent.getStreamsWithPendingConnectivityEstablishment();

        if (streamsWithPendingConnectivityEstablishment.size() > 0) {
            // cmeng (20220613): must init to false to re-active startChecks(), previously stop() when terminated.
            // Otherwise content-add not working with init with audio call
            stopped = false;
            logger.info("Start connectivity checks. Local ufrag " + parentAgent.getLocalUfrag());
            startChecks(streamsWithPendingConnectivityEstablishment.get(0).getCheckList());
        }
        else {
            logger.info("Not starting any checks, because there are no pending streams.");
        }
    }

bgrozev commented 2 years ago

Does this happen with the Jitsi desktop client? Do you know what Agent APIs it uses when it does a "content-add"?

cmeng-git commented 2 years ago

The problem is observed on aTalk, development is on Ubuntu 22.04. Jitsi desktop failed to install on this ubuntu platform. When using virtualBox, Jitsi cannot recognise the pass-through camera device. Do I am unable to verify Jitsi desktop. However based on the ice4j source, I believe this should happen on Jisti desktop.

With reference to ice4j 3.0 source: The Agent will scheduleTermination() at the end of the audio call setup since all remote pairing process has completed. This will set ConnectivityCheckClient#stopped to true;


    /**
     * Initializes and starts the {@link #terminationFuture}
     */
    private void scheduleTermination()
    {
        /*
         * RFC 5245 says: Once ICE processing has reached the Completed state for
         * all peers for media streams using those candidates, the agent SHOULD
         * wait an additional three seconds, and then it MAY cease responding to
         * checks or generating triggered checks on that candidate.  It MAY free
         * the candidate at that time.
         * <p>
         * This method is scheduling such a termination.
         */
        boolean runTerminationImmediately = false;

        synchronized (terminationFutureSyncRoot) {
            if (terminationFuture == null) {
                long terminationDelay = Integer.getInteger(StackProperties.TERMINATION_DELAY, DEFAULT_TERMINATION_DELAY);

                if (terminationDelay > 0) {
                    terminationFuture = agentTasksScheduler.schedule(
                            terminationRunnable,
                            terminationDelay,
                            TimeUnit.MILLISECONDS);
                }
                else {
                    runTerminationImmediately = true;
                }
            }
        }

        if (runTerminationImmediately) {
            terminationRunnable.run();
        }
    }

When user enables video in a audio only call, the app executes the jingle content-add as aspected. From aTalk logcat, I see that all process in video call setup is working correctly. However it does not proceed with the pairing check after

2022-06-14 07:59:40.180 10876-12288/org.atalk.android I/aTalk: [1310] org.ice4j.ice.ConnectivityCheckClient.log() Start connectivity checks. Local ufrag ps6s1g5fo3vfu.

On debug, the whole process does not proceed is due to stopped flag is set to true as explained above. I see that there is no other area the stopped flag get reinit when the following is being called:

2022-06-14 07:59:40.174 10876-12288/org.atalk.android I/aTalk: [1310] org.ice4j.ice.Agent.log() Start ICE connectivity establishment. Local ufrag ps6s1g5fo3vfu

due to

            if (stopped) {
                return;
            }

    /**
     * Starts client connectivity checks for the {@link CandidatePair}s in <tt>checkList</tt>
     *
     * @param checkList the {@link CheckList} to start client side connectivity checks for.
     */
    public void startChecks(CheckList checkList)
    {
        synchronized (paceMakers) {
            if (stopped) {
                return;
            }
            PaceMaker paceMaker = new PaceMaker(checkList);
            paceMakers.add(paceMaker);
            paceMaker.schedule();
        }
    }

// =========== aTalk logcat ===============
2022-06-14 07:59:40.155 10876-32575/org.atalk.android D/SMACK: RECV (0): 
    <iq xml:lang='en' to='swordfish@atalk.sytes.net/atalk' from='peacock@atalk.sytes.net/atalk' type='set' id='FSEHI-25'>
      <jingle xmlns='urn:xmpp:jingle:1' initiator='peacock@atalk.sytes.net/atalk' action='transport-info' sid='QD8F57XNFAMQUSA7C4BEKBFZ'>
        <content creator='initiator' name='video' senders='initiator'>
          <transport xmlns='urn:xmpp:jingle:transports:ice-udp:1' ufrag='drdmo1g5fo4355' pwd='6kur1rqvnddla7o8i6rkmmtg91'>
            <rtcp-mux/>
            <candidate foundation='1' component='1' protocol='udp' priority='2130706431' generation='0' id='5' ip='fe80::362d:dff:fe00:ae96' port='5001' type='host' network='0'/>
            <candidate foundation='2' component='1' protocol='udp' priority='2130706431' generation='0' id='6' ip='192.168.1.37' port='5001' type='host' network='0'/>
            <candidate foundation='4' component='1' protocol='udp' priority='1677724415' generation='0' id='7' ip='42.60.7.13' port='1404' type='srflx' rel-addr='192.168.1.37' rel-port='5001' network='0'/>
            <candidate foundation='3' component='1' protocol='udp' priority='2815' generation='0' id='8' ip='42.60.7.13' port='51007' type='relay' network='0'/>
          </transport>
        </content>
      </jingle>
    </iq>
2022-06-14 07:59:40.161 10876-32575/org.atalk.android D/SMACK: RECV (0): 
    <r xmlns='urn:xmpp:sm:3'/>
2022-06-14 07:59:40.162 10876-12288/org.atalk.android D/(OperationSetBasicTelephonyJabberImpl.java:955)#processJingle: ### Processing Jingle IQ (transport-info: FSEHI-25); callPeer: peacock@atalk.sytes.net/atalk
2022-06-14 07:59:40.162 10876-12288/org.atalk.android D/(OperationSetBasicTelephonyJabberImpl.java:1193)#processTransportInfo: ### Process Jingle transport-info (session-accept) media: []; null
2022-06-14 07:59:40.163 10876-12288/org.atalk.android D/(CallPeerJabberImpl.java:873)#processOfferTransportInfo: ### Processing Jingle (transport-info) for media: [video] : FSEHI-25
2022-06-14 07:59:40.164 10876-32574/org.atalk.android D/SMACK: SENT (0): 
    <iq to='peacock@atalk.sytes.net/atalk' id='FSEHI-25' type='result'>
    </iq>
    <a xmlns='urn:xmpp:sm:3' h='403'/>
2022-06-14 07:59:40.168 10876-12288/org.atalk.android I/aTalk: [1310] org.ice4j.ice.Component.log() Add remote candidate for video.RTP: [fe80::362d:dff:fe00:ae96]:5001/udp/host
2022-06-14 07:59:40.169 10876-12288/org.atalk.android I/aTalk: [1310] org.ice4j.ice.Component.log() Add remote candidate for video.RTP: 192.168.1.37:5001/udp/host
2022-06-14 07:59:40.171 10876-12288/org.atalk.android I/aTalk: [1310] org.ice4j.ice.Component.log() Add remote candidate for video.RTP: 42.60.7.13:1404/udp/srflx
2022-06-14 07:59:40.172 10876-12288/org.atalk.android I/aTalk: [1310] org.ice4j.ice.Component.log() Add remote candidate for video.RTP: 42.60.7.13:51007/udp/relay
2022-06-14 07:59:40.174 10876-12288/org.atalk.android I/aTalk: [1310] org.ice4j.ice.Agent.log() Start ICE connectivity establishment. Local ufrag ps6s1g5fo3vfu
2022-06-14 07:59:40.175 10876-12288/org.atalk.android I/aTalk: [1310] org.ice4j.ice.Agent.log() Init checklist for stream video
2022-06-14 07:59:40.177 10876-12288/org.atalk.android D/aTalk: [1310] org.ice4j.ice.IceMediaStream.log() Checklist initialized.
2022-06-14 07:59:40.178 10876-12288/org.atalk.android I/aTalk: [1310] org.ice4j.ice.Agent.log() ICE state changed from Waiting to Running. Local ufrag ps6s1g5fo3vfu
2022-06-14 07:59:40.180 10876-12288/org.atalk.android I/aTalk: [1310] org.ice4j.ice.ConnectivityCheckClient.log() Start connectivity checks. Local ufrag ps6s1g5fo3vfu

jitsi / ice4j

ice4j 3.0 cannot support video content-add when initial call starts with audio only #263