jitsi/ice4j

QUESTION: How to connect faster?

jvmusin opened this issue · 1 comments

Hi.

Not an issue actually, but a question. Is it normal that it takes about three seconds to connect my machine from one port to another? And how can I make it faster?

Sorry if this question has already been asked, I couldn't find it in issues.

I use this snippet

fun newAgent(port: Int): Agent {
    val agent = Agent()

    val stream = agent.createMediaStream("data")
    agent.createComponent(stream, Transport.UDP, port, port, port + 100) // RTP

    return agent
}
val agent1 = newAgent(8081)
val agent2 = newAgent(8082)
val sdp1 = SdpUtils.createSDPDescription(agent1)
val sdp2 = SdpUtils.createSDPDescription(agent2)
SdpUtils.parseSDP(agent1, sdp2)
SdpUtils.parseSDP(agent2, sdp1)
thread { agent1.startConnectivityEstablishment() }
thread { agent2.startConnectivityEstablishment() }
Thread.sleep(10_000)

And it writes this to the console

long logs

Jul 23, 2021 8:20:18 PM org.jitsi.utils.logging2.LoggerImpl log
INFO: Initialized newConfig: merge of system properties,reference.conf @ jar:file:/Users/Rustam.Musin/.gradle/caches/modules-2/files-2.1/org.jitsi/ice4j/3.0-33-g311a495/f26cf91503637d8e7583306cc767455168b15246/ice4j-3.0-33-g311a495.jar!/reference.conf: 1
Jul 23, 2021 8:20:18 PM org.jitsi.utils.logging2.LoggerImpl log
INFO: net.java.sip.communicator.SC_HOME_DIR_LOCATION not set
Jul 23, 2021 8:20:18 PM org.jitsi.utils.logging2.LoggerImpl log
INFO: Initialized legacyConfig: sip communicator props (no description provided)
Jul 23, 2021 8:20:18 PM org.ice4j.ice.harvest.MappingCandidateHarvesters initialize
INFO: Using AwsCandidateHarvester.
Jul 23, 2021 8:20:19 PM org.ice4j.ice.harvest.MappingCandidateHarvesters maybeAdd
INFO: Discarding a mapping harvester: org.ice4j.ice.harvest.AwsCandidateHarvester, face=null, mask=null
Jul 23, 2021 8:20:19 PM org.ice4j.ice.harvest.MappingCandidateHarvesters initialize
INFO: Initialized mapping harvesters (delay=530ms). stunDiscoveryFailed=false
Jul 23, 2021 8:20:19 PM org.jitsi.utils.logging2.LoggerImpl log
INFO: Gathering candidates for component data.RTP.
Jul 23, 2021 8:20:19 PM org.jitsi.utils.logging2.LoggerImpl log
INFO: Gathering candidates for component data.RTP.
Jul 23, 2021 8:20:19 PM org.jitsi.utils.logging2.LoggerImpl log
INFO: Add remote candidate for data.RTP: 192.168.0.107:8082/udp/host
Jul 23, 2021 8:20:19 PM org.jitsi.utils.logging2.LoggerImpl log
INFO: Add remote candidate for data.RTP: 192.168.0.107:8081/udp/host
Jul 23, 2021 8:20:19 PM org.jitsi.utils.logging2.LoggerImpl log
INFO: Start ICE connectivity establishment.
Jul 23, 2021 8:20:19 PM org.jitsi.utils.logging2.LoggerImpl log
INFO: Start ICE connectivity establishment.
Jul 23, 2021 8:20:19 PM org.jitsi.utils.logging2.LoggerImpl log
INFO: Init checklist for stream data
Jul 23, 2021 8:20:19 PM org.jitsi.utils.logging2.LoggerImpl log
INFO: Init checklist for stream data
Jul 23, 2021 8:20:19 PM org.jitsi.utils.logging2.LoggerImpl log
INFO: ICE state changed from Waiting to Running.
Jul 23, 2021 8:20:19 PM org.jitsi.utils.logging2.LoggerImpl log
INFO: ICE state changed from Waiting to Running.
Jul 23, 2021 8:20:19 PM org.jitsi.utils.logging2.LoggerImpl log
INFO: Start connectivity checks.
Jul 23, 2021 8:20:19 PM org.jitsi.utils.logging2.LoggerImpl log
INFO: Start connectivity checks.
Jul 23, 2021 8:20:19 PM org.jitsi.utils.logging2.LoggerImpl log
INFO: Changing agent ICE Agent (stream-count=1 ice-pwd:5tb8i2au0dvg6s4mjrhl7g840r ice-ufrag:dhb801fba63kt1 tie-breaker:3260598790436055336):
media stream:data (component count=1)
Component id=1 parent stream=data
1 Local candidates:
default candidate: candidate:1 1 udp 2130706431 192.168.0.107 8081 typ host
candidate:1 1 udp 2130706431 192.168.0.107 8081 typ host
1 Remote candidates:
default remote candidate: candidate:1 1 udp 2130706431 192.168.0.107 8082 typ host
candidate:1 1 udp 2130706431 192.168.0.107 8082 typ host
role from controlling = true to controlling = false
Jul 23, 2021 8:20:19 PM org.jitsi.utils.logging2.LoggerImpl log
INFO: Changing agent ICE Agent (stream-count=1 ice-pwd:5tb8i2au0dvg6s4mjrhl7g840r ice-ufrag:dhb801fba63kt1 tie-breaker:3260598790436055336):
media stream:data (component count=1)
Component id=1 parent stream=data
1 Local candidates:
default candidate: candidate:1 1 udp 2130706431 192.168.0.107 8081 typ host
candidate:1 1 udp 2130706431 192.168.0.107 8081 typ host
1 Remote candidates:
default remote candidate: candidate:1 1 udp 2130706431 192.168.0.107 8082 typ host
candidate:1 1 udp 2130706431 192.168.0.107 8082 typ host
role from controlling = false to controlling = false
Jul 23, 2021 8:20:19 PM org.jitsi.utils.logging2.LoggerImpl log
INFO: Pair succeeded: 192.168.0.107:8082/udp/host -> 192.168.0.107:8081/udp/host (data.RTP).
Jul 23, 2021 8:20:19 PM org.jitsi.utils.logging2.LoggerImpl log
INFO: Adding allowed address: 192.168.0.107:8081/udp
Jul 23, 2021 8:20:19 PM org.jitsi.utils.logging2.LoggerImpl log
INFO: Pair validated: 192.168.0.107:8082/udp/host -> 192.168.0.107:8081/udp/host (data.RTP).
Jul 23, 2021 8:20:19 PM org.jitsi.utils.logging2.LoggerImpl log
INFO: Nominate (first valid): 192.168.0.107:8082/udp/host -> 192.168.0.107:8081/udp/host (data.RTP).
Jul 23, 2021 8:20:19 PM org.jitsi.utils.logging2.LoggerImpl log
INFO: verify if nominated pair answer again
Jul 23, 2021 8:20:19 PM org.jitsi.utils.logging2.LoggerImpl log
INFO: IsControlling: true USE-CANDIDATE:false.
Jul 23, 2021 8:20:19 PM org.jitsi.utils.logging2.LoggerImpl log
INFO: Pair succeeded: 192.168.0.107:8081/udp/host -> 192.168.0.107:8082/udp/host (data.RTP).
Jul 23, 2021 8:20:19 PM org.jitsi.utils.logging2.LoggerImpl log
INFO: Pair succeeded: 192.168.0.107:8082/udp/host -> 192.168.0.107:8081/udp/host (data.RTP).
Jul 23, 2021 8:20:19 PM org.jitsi.utils.logging2.LoggerImpl log
INFO: Adding allowed address: 192.168.0.107:8082/udp
Jul 23, 2021 8:20:19 PM org.jitsi.utils.logging2.LoggerImpl log
INFO: IsControlling: true USE-CANDIDATE:true.
Jul 23, 2021 8:20:19 PM org.jitsi.utils.logging2.LoggerImpl log
INFO: Pair validated: 192.168.0.107:8081/udp/host -> 192.168.0.107:8082/udp/host (data.RTP).
Jul 23, 2021 8:20:19 PM org.jitsi.utils.logging2.LoggerImpl log
INFO: Nomination confirmed for pair: 192.168.0.107:8082/udp/host -> 192.168.0.107:8081/udp/host (data.RTP).
Jul 23, 2021 8:20:19 PM org.jitsi.utils.logging2.LoggerImpl log
INFO: IsControlling: false USE-CANDIDATE:false.
Jul 23, 2021 8:20:19 PM org.jitsi.utils.logging2.LoggerImpl log
INFO: Nomination confirmed for pair: 192.168.0.107:8081/udp/host -> 192.168.0.107:8082/udp/host (data.RTP)
Jul 23, 2021 8:20:19 PM org.jitsi.utils.logging2.LoggerImpl log
INFO: Selected pair for stream data.RTP: 192.168.0.107:8082/udp/host -> 192.168.0.107:8081/udp/host (data.RTP)
Jul 23, 2021 8:20:19 PM org.jitsi.utils.logging2.LoggerImpl log
INFO: Selected pair for stream data.RTP: 192.168.0.107:8081/udp/host -> 192.168.0.107:8082/udp/host (data.RTP)
Jul 23, 2021 8:20:19 PM org.jitsi.utils.logging2.LoggerImpl log
INFO: CheckList of stream data is COMPLETED
Jul 23, 2021 8:20:19 PM org.jitsi.utils.logging2.LoggerImpl log
INFO: CheckList of stream data is COMPLETED
Jul 23, 2021 8:20:19 PM org.jitsi.utils.logging2.LoggerImpl log
INFO: ICE state changed from Running to Completed.
Jul 23, 2021 8:20:19 PM org.jitsi.utils.logging2.LoggerImpl log
INFO: ICE state changed from Running to Completed.
Jul 23, 2021 8:20:19 PM org.jitsi.utils.logging2.LoggerImpl log
INFO: Harvester used for selected pair for data.RTP: host
Jul 23, 2021 8:20:19 PM org.jitsi.utils.logging2.LoggerImpl log
INFO: Harvester used for selected pair for data.RTP: host
Jul 23, 2021 8:20:22 PM org.jitsi.utils.logging2.LoggerImpl log
INFO: ICE state changed from Completed to Terminated.
Jul 23, 2021 8:20:22 PM org.jitsi.utils.logging2.LoggerImpl log
INFO: ICE state changed from Completed to Terminated.

In the very end of the logs you can see a pause between 8:20:19 and 8:20:22 where nothing happens and only after the last message we can use the established connection.

Hey @jvmusin. The transition from Running to Completed is when the connection succeeded and is ready to be used. The subsquent trransition to Terminated is scheduled for 3 seconds layter, and it just indicates that unused candidates are cleared.