Suspicious ICE Connectivity Failure


#1

I have a client attempting to join a Jitsi Videobridge conference. Both the client and Videobridge are running on my local machine. The host candidate pairs are accepted on both sides during ice exchange.

On the client, ice appears to complete successfully and proceeds to send DTLS ClientHello packets.

On the Videobridge side, the ice checklists never complete. End up with “Suspicious ICE connectivity failure. Checks failed but the remote end was able to reach us.”

I’m running everything locally.

This is the setup:

  • In a browser (192.168.1.98), navigate to the jitsi meet page (192.168.1.99 and start a conference
  • Use the client which is also on 192.168.1.98 to connect to the conference.

The user from the client joins the conference, but no media flow is established due to the ice failure on the Videobridge side.

This is the log of the ice exchange:

JVB 2019-01-11 13:46:56.309 FINE: [117] org.jitsi.videobridge.xmpp.ComponentImpl.log() RECV: <iq type="set" to="jitsi-videobridge.dev.jitsi.com" from="focus@auth.dev.jitsi.com/focus147991558819406" id="FTVGA-4989"><conference xmlns="http://jitsi.org/protocol/colibri" id="a0dd070ffddc6f07" name="454645646" gid="ff47a"><content name="audio"><channel id="7400d5a0a268cffd"><payload-type id="126" name="telephone-event" clockrate="8000"/></channel><channel id="7400d5a0a268cffd" endpoint="1683ee171bb"><transport xmlns="urn:xmpp:jingle:transports:ice-udp:1" ufrag="4703aaf0" pwd="5ac80ea687484fed93e34375d3b53617"><fingerprint xmlns="urn:xmpp:jingle:apps:dtls:0" hash="sha-256" setup="active" required="false">6E:08:AA:28:6E:D5:0A:61:E1:BD:39:53:C5:23:AC:1C:EC:CE:74:60:90:E4:33:A6:A8:65:A6:29:A5:14:AA:13</fingerprint><candidate component="1" port="55734" foundation="3471325031" type="host" priority="2122294527" protocol="udp" ip="10.37.129.2"/><candidate component="1" port="59514" foundation="4119821504" type="host" priority="2122294271" protocol="udp" ip="10.211.55.2"/><candidate component="1" port="60206" foundation="3864524993" type="host" priority="2122294015" protocol="udp" ip="2001:569:7b65:ce00:5892:77:c63e:7a92"/><candidate component="1" port="52604" foundation="2345422095" type="host" priority="2122293759" protocol="udp" ip="2001:569:7b65:ce00:1842:287:9a43:2274"/><candidate component="1" port="53180" foundation="2798468125" type="host" priority="2122293503" protocol="udp" ip="192.168.1.98"/></transport></channel></content><content name="video"><channel id="9f53c7cd377d4f8c"><payload-type id="100" name="VP8" clockrate="90000"/><payload-type id="101" name="VP9" clockrate="90000"/></channel><channel id="9f53c7cd377d4f8c" endpoint="1683ee171bb"><transport xmlns="urn:xmpp:jingle:transports:ice-udp:1" ufrag="7175e850" pwd="9e7821c72f2a4bb591f4f3256c7518b8"><fingerprint xmlns="urn:xmpp:jingle:apps:dtls:0" hash="sha-256" setup="active" required="false">6E:08:AA:28:6E:D5:0A:61:E1:BD:39:53:C5:23:AC:1C:EC:CE:74:60:90:E4:33:A6:A8:65:A6:29:A5:14:AA:13</fingerprint><candidate component="1" port="54302" foundation="3471325031" type="host" priority="2122294527" protocol="udp" ip="10.37.129.2"/><candidate component="1" port="49290" foundation="4119821504" type="host" priority="2122294271" protocol="udp" ip="10.211.55.2"/><candidate component="1" port="54596" foundation="3864524993" type="host" priority="2122294015" protocol="udp" ip="2001:569:7b65:ce00:5892:77:c63e:7a92"/><candidate component="1" port="64534" foundation="2345422095" type="host" priority="2122293759" protocol="udp" ip="2001:569:7b65:ce00:1842:287:9a43:2274"/><candidate component="1" port="63550" foundation="2798468125" type="host" priority="2122293503" protocol="udp" ip="192.168.1.98"/></transport></channel></content></conference></iq>
JVB 2019-01-11 13:46:56.320 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Will parse payload-type ns=http://jitsi.org/protocol/colibri class=PayloadTypePacketExtension
JVB 2019-01-11 13:46:56.321 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Done parsing payload-type
JVB 2019-01-11 13:46:56.321 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Will parse fingerprint ns=urn:xmpp:jingle:apps:dtls:0 class=IceUdpTransportPacketExtension
JVB 2019-01-11 13:46:56.321 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Will parse null ns=null class=DtlsFingerprintPacketExtension
JVB 2019-01-11 13:46:56.321 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Done parsing null
JVB 2019-01-11 13:46:56.321 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Will parse fingerprint ns=urn:xmpp:jingle:apps:dtls:0 class=DtlsFingerprintPacketExtension
JVB 2019-01-11 13:46:56.321 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Done parsing fingerprint
JVB 2019-01-11 13:46:56.322 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Done parsing fingerprint
JVB 2019-01-11 13:46:56.322 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Will parse candidate ns=urn:xmpp:jingle:transports:ice-udp:1 class=IceUdpTransportPacketExtension
JVB 2019-01-11 13:46:56.322 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Will parse candidate ns=urn:xmpp:jingle:transports:ice-udp:1 class=CandidatePacketExtension
JVB 2019-01-11 13:46:56.322 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Done parsing candidate
JVB 2019-01-11 13:46:56.322 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Done parsing candidate
JVB 2019-01-11 13:46:56.322 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Will parse candidate ns=urn:xmpp:jingle:transports:ice-udp:1 class=IceUdpTransportPacketExtension
JVB 2019-01-11 13:46:56.322 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Will parse candidate ns=urn:xmpp:jingle:transports:ice-udp:1 class=CandidatePacketExtension
JVB 2019-01-11 13:46:56.322 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Done parsing candidate
JVB 2019-01-11 13:46:56.322 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Done parsing candidate
JVB 2019-01-11 13:46:56.323 FINEST: [42601] org.ice4j.stack.Connector.run() received datagram packet - addr: /192.168.1.98 port: 63550
JVB 2019-01-11 13:46:56.323 FINEST: [42599] org.ice4j.stack.MessageProcessor.run() Dispatching a StunMessageEvent.
JVB 2019-01-11 13:46:56.323 FINEST: [42599] org.ice4j.stack.StunStack.handleMessageEvent() Received a message on 192.168.1.99:14647/udp of type:1
JVB 2019-01-11 13:46:56.323 FINEST: [42599] org.ice4j.stack.StunStack.handleMessageEvent() parsing request
JVB 2019-01-11 13:46:56.323 FINEST: [42599] org.ice4j.stack.StunStack.handleMessageEvent() existing transaction not found
JVB 2019-01-11 13:46:56.323 FINEST: [42599] org.ice4j.stack.StunStack.validateMessageIntegrity() Successfully verified msg integrity
JVB 2019-01-11 13:46:56.327 FINE: [42627] org.jitsi.impl.neomedia.transform.srtp.SRTPCryptoContext.log() Reverse transform for SSRC 1267383257 SeqNo=26830 s_l=26829 seqNumSet=true guessedROC=0 roc=0
JVB 2019-01-11 13:46:56.327 FINE: [42627] org.jitsi.impl.neomedia.transform.DiscardTransformEngine.log() passing through  RTP ssrc=1267383257, seqnum=26830, ts=1430509413, streamHashCode=1590246027
JVB 2019-01-11 13:46:56.327 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Will parse candidate ns=urn:xmpp:jingle:transports:ice-udp:1 class=IceUdpTransportPacketExtension
JVB 2019-01-11 13:46:56.327 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Will parse candidate ns=urn:xmpp:jingle:transports:ice-udp:1 class=CandidatePacketExtension
JVB 2019-01-11 13:46:56.327 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Done parsing candidate
JVB 2019-01-11 13:46:56.327 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Done parsing candidate
JVB 2019-01-11 13:46:56.327 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Will parse candidate ns=urn:xmpp:jingle:transports:ice-udp:1 class=IceUdpTransportPacketExtension
JVB 2019-01-11 13:46:56.328 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Will parse candidate ns=urn:xmpp:jingle:transports:ice-udp:1 class=CandidatePacketExtension
JVB 2019-01-11 13:46:56.328 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Done parsing candidate
JVB 2019-01-11 13:46:56.328 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Done parsing candidate
JVB 2019-01-11 13:46:56.328 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Will parse candidate ns=urn:xmpp:jingle:transports:ice-udp:1 class=IceUdpTransportPacketExtension
JVB 2019-01-11 13:46:56.328 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Will parse candidate ns=urn:xmpp:jingle:transports:ice-udp:1 class=CandidatePacketExtension
JVB 2019-01-11 13:46:56.328 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Done parsing candidate
JVB 2019-01-11 13:46:56.328 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Done parsing candidate
JVB 2019-01-11 13:46:56.328 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Will parse transport ns=urn:xmpp:jingle:transports:ice-udp:1 class=IceUdpTransportPacketExtension
JVB 2019-01-11 13:46:56.328 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Done parsing transport
JVB 2019-01-11 13:46:56.328 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Will parse payload-type ns=http://jitsi.org/protocol/colibri class=PayloadTypePacketExtension
JVB 2019-01-11 13:46:56.329 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Done parsing payload-type
JVB 2019-01-11 13:46:56.329 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Will parse payload-type ns=http://jitsi.org/protocol/colibri class=PayloadTypePacketExtension
JVB 2019-01-11 13:46:56.329 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Done parsing payload-type
JVB 2019-01-11 13:46:56.329 FINEST: [42593] org.ice4j.stack.Connector.run() received datagram packet - addr: /192.168.1.98 port: 53180
JVB 2019-01-11 13:46:56.329 FINER: [42638] timeseries.org.jitsi.impl.neomedia.rtp.TransportCCEngine.log() {"conf_creation_time_ms":1547243189053,"video_stream":1392206704,"pt":100,"conf_name":"454645646","series":"ingress_tcc_pkt","transport":161141499,"time":"1547243216.329000000","seq":10053}
JVB 2019-01-11 13:46:56.329 FINE: [42638] org.jitsi.impl.neomedia.transform.srtp.SRTPCryptoContext.log() Reverse transform for SSRC 713663915 SeqNo=27191 s_l=27190 seqNumSet=true guessedROC=0 roc=0
JVB 2019-01-11 13:46:56.329 FINER: [42638] org.jitsi.impl.neomedia.rtp.RawPacketCache.log() Caching a packet. SSRC=713663915 seq=27191
JVB 2019-01-11 13:46:56.329 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Will parse fingerprint ns=urn:xmpp:jingle:apps:dtls:0 class=IceUdpTransportPacketExtension
JVB 2019-01-11 13:46:56.329 FINEST: [42591] org.ice4j.stack.MessageProcessor.run() Dispatching a StunMessageEvent.
JVB 2019-01-11 13:46:56.329 FINEST: [42591] org.ice4j.stack.StunStack.handleMessageEvent() Received a message on 192.168.1.99:14645/udp of type:1
JVB 2019-01-11 13:46:56.330 FINEST: [42591] org.ice4j.stack.StunStack.handleMessageEvent() parsing request
JVB 2019-01-11 13:46:56.330 FINEST: [42591] org.ice4j.stack.StunStack.handleMessageEvent() existing transaction not found
JVB 2019-01-11 13:46:56.330 FINEST: [42591] org.ice4j.stack.StunStack.validateMessageIntegrity() Successfully verified msg integrity
JVB 2019-01-11 13:46:56.333 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Will parse null ns=null class=DtlsFingerprintPacketExtension
JVB 2019-01-11 13:46:56.333 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Done parsing null
JVB 2019-01-11 13:46:56.333 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Will parse fingerprint ns=urn:xmpp:jingle:apps:dtls:0 class=DtlsFingerprintPacketExtension
JVB 2019-01-11 13:46:56.333 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Done parsing fingerprint
JVB 2019-01-11 13:46:56.333 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Done parsing fingerprint
JVB 2019-01-11 13:46:56.333 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Will parse candidate ns=urn:xmpp:jingle:transports:ice-udp:1 class=IceUdpTransportPacketExtension
JVB 2019-01-11 13:46:56.334 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Will parse candidate ns=urn:xmpp:jingle:transports:ice-udp:1 class=CandidatePacketExtension
JVB 2019-01-11 13:46:56.334 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Done parsing candidate
JVB 2019-01-11 13:46:56.334 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Done parsing candidate
JVB 2019-01-11 13:46:56.334 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Will parse candidate ns=urn:xmpp:jingle:transports:ice-udp:1 class=IceUdpTransportPacketExtension
JVB 2019-01-11 13:46:56.334 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Will parse candidate ns=urn:xmpp:jingle:transports:ice-udp:1 class=CandidatePacketExtension
JVB 2019-01-11 13:46:56.334 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Done parsing candidate
JVB 2019-01-11 13:46:56.334 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Done parsing candidate
JVB 2019-01-11 13:46:56.335 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Will parse candidate ns=urn:xmpp:jingle:transports:ice-udp:1 class=IceUdpTransportPacketExtension
JVB 2019-01-11 13:46:56.335 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Will parse candidate ns=urn:xmpp:jingle:transports:ice-udp:1 class=CandidatePacketExtension
JVB 2019-01-11 13:46:56.335 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Done parsing candidate
JVB 2019-01-11 13:46:56.339 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Done parsing candidate
JVB 2019-01-11 13:46:56.339 FINEST: [117] impl.protocol.jabber.extensions.DefaultPacketExtensionProvider.parse() Will parse candidate ns=urn:xmpp:jingle:transports:ice-udp:1 class=IceUdpTransportPacketExtension
JVB 2019-01-11 13:46:56.373 INFO: [117] org.ice4j.ice.Agent.log() Start ICE connectivity establishment. Local ufrag 50ete1d0ve2stg
JVB 2019-01-11 13:46:56.373 INFO: [117] org.ice4j.ice.Agent.log() Init checklist for stream stream
JVB 2019-01-11 13:46:56.374 INFO: [117] org.ice4j.ice.Agent.log() ICE state changed from Waiting to Running. Local ufrag 50ete1d0ve2stg
JVB 2019-01-11 13:46:56.374 INFO: [117] org.jitsi.videobridge.IceUdpTransportManager.log() CAT=stat ice_state_change,conf_id=a0dd070ffddc6f07,content=audio,ch_id=7400d5a0a268cffd,endp_id=1683ee171bb old_state=Waiting,new_state=Running
JVB 2019-01-11 13:46:56.374 INFO: [117] org.ice4j.ice.Agent.log() Trigger checks for pairs that were received before running state
JVB 2019-01-11 13:46:56.375 INFO: [117] org.ice4j.ice.Agent.log() Add peer CandidatePair with new reflexive address to checkList: CandidatePair (State=Frozen Priority=7962260787064471551):
	LocalCandidate=candidate:1 1 udp 2130706431 192.168.1.99 14645 typ host
	RemoteCandidate=candidate:10000 1 udp 1853858303 192.168.1.98 53180 typ prflx
JVB 2019-01-11 13:46:56.385 INFO: [117] org.ice4j.ice.ConnectivityCheckClient.log() Start connectivity checks. Local ufrag 50ete1d0ve2stg
JVB 2019-01-11 13:46:56.407 INFO: [117] org.jitsi.videobridge.IceUdpTransportManager.log() Starting ICE agent without remote candidates.
JVB 2019-01-11 13:46:56.408 INFO: [117] org.ice4j.ice.Agent.log() Start ICE connectivity establishment. Local ufrag 21apm1d0ve2sts
JVB 2019-01-11 13:46:56.408 FINE: [42770] org.ice4j.stack.StunClientTransaction.sendRequest() sending STUN  tid 0x14DEE13E6801D9700FBDA6D0 from 192.168.1.99:14645/udp to 192.168.1.98:53180/udp
JVB 2019-01-11 13:46:56.409 FINER: [42632] org.jitsi.impl.neomedia.rtp.translator.RTPTranslatorImpl.log() org.jitsi.impl.neomedia.rtp.translator.RTPTranslatorImpl.read: RTCP BYE SSRC/CSRC 685613860
JVB 2019-01-11 13:46:56.409 INFO: [117] org.ice4j.ice.Agent.log() Init checklist for stream stream
JVB 2019-01-11 13:46:56.409 INFO: [117] org.ice4j.ice.Agent.log() ICE state changed from Waiting to Running. Local ufrag 21apm1d0ve2sts
JVB 2019-01-11 13:46:56.409 INFO: [117] org.jitsi.videobridge.IceUdpTransportManager.log() CAT=stat ice_state_change,conf_id=a0dd070ffddc6f07,content=video,ch_id=9f53c7cd377d4f8c,endp_id=1683ee171bb old_state=Waiting,new_state=Running
JVB 2019-01-11 13:46:56.409 INFO: [117] org.ice4j.ice.Agent.log() Trigger checks for pairs that were received before running state
JVB 2019-01-11 13:46:56.410 INFO: [117] org.ice4j.ice.Agent.log() Add peer CandidatePair with new reflexive address to checkList: CandidatePair (State=Frozen Priority=7962260787064471551):
	LocalCandidate=candidate:1 1 udp 2130706431 192.168.1.99 14647 typ host
	RemoteCandidate=candidate:10000 1 udp 1853858303 192.168.1.98 63550 typ prflx
JVB 2019-01-11 13:46:56.413 FINEST: [42593] org.ice4j.stack.Connector.run() received datagram packet - addr: /192.168.1.98 port: 53180
JVB 2019-01-11 13:46:56.414 INFO: [117] org.ice4j.ice.ConnectivityCheckClient.log() Start connectivity checks. Local ufrag 21apm1d0ve2sts
JVB 2019-01-11 13:46:56.414 FINEST: [42592] org.ice4j.stack.MessageProcessor.run() Dispatching a StunMessageEvent.
JVB 2019-01-11 13:46:56.414 FINEST: [42592] org.ice4j.stack.StunStack.handleMessageEvent() Received a message on 192.168.1.99:14645/udp of type:257
JVB 2019-01-11 13:46:56.415 FINE: [42592] org.ice4j.stack.StunClientTransaction.handleResponse() handleResponse tid 0x14DEE13E6801D9700FBDA6D0
JVB 2019-01-11 13:46:56.415 INFO: [42592] org.ice4j.ice.ConnectivityCheckClient.log() Pair succeeded: 192.168.1.99:14645/udp/host -> 192.168.1.98:53180/udp/prflx (stream.RTP). Local ufrag 50ete1d0ve2stg
JVB 2019-01-11 13:46:56.415 INFO: [42592] org.ice4j.socket.MergingDatagramSocket.log() Adding allowed address: 192.168.1.98:53180/udp
JVB 2019-01-11 13:46:56.416 INFO: [42592] org.ice4j.ice.ConnectivityCheckClient.log() Pair validated: 192.168.1.99:14645/udp/host -> 192.168.1.98:53180/udp/prflx (stream.RTP). Local ufrag 50ete1d0ve2stg
JVB 2019-01-11 13:46:56.416 INFO: [42592] org.ice4j.ice.DefaultNominator.log() Nominate (first valid): 192.168.1.99:14645/udp/host -> 192.168.1.98:53180/udp/prflx (stream.RTP). Local ufrag 50ete1d0ve2stg
JVB 2019-01-11 13:46:56.416 INFO: [42592] org.ice4j.ice.Agent.log() verify if nominated pair answer again
JVB 2019-01-11 13:46:56.417 INFO: [42592] org.ice4j.ice.ConnectivityCheckClient.log() IsControlling: true USE-CANDIDATE:false. Local ufrag 50ete1d0ve2stg
JVB 2019-01-11 13:46:56.428 FINER: [42638] org.jitsi.impl.neomedia.rtp.RawPacketCache.log() Caching a packet. SSRC=713663915 seq=27202
JVB 2019-01-11 13:46:56.428 FINER: [42638] timeseries.org.jitsi.impl.neomedia.rtp.TransportCCEngine.log() {"conf_creation_time_ms":1547243189053,"video_stream":1392206704,"pt":100,"conf_name":"454645646","series":"ingress_tcc_pkt","transport":161141499,"time":"1547243216.428000000","seq":10065}
JVB 2019-01-11 13:46:56.429 FINE: [42638] org.jitsi.impl.neomedia.transform.srtp.SRTPCryptoContext.log() Reverse transform for SSRC 713663915 SeqNo=27203 s_l=27202 seqNumSet=true guessedROC=0 roc=0
JVB 2019-01-11 13:46:56.429 FINER: [42638] org.jitsi.impl.neomedia.rtp.RawPacketCache.log() Caching a packet. SSRC=713663915 seq=27203
JVB 2019-01-11 13:46:56.429 FINE: [42627] org.jitsi.impl.neomedia.transform.srtp.SRTPCryptoContext.log() Reverse transform for SSRC 1267383257 SeqNo=26835 s_l=26834 seqNumSet=true guessedROC=0 roc=0
JVB 2019-01-11 13:46:56.429 FINE: [42627] org.jitsi.impl.neomedia.transform.DiscardTransformEngine.log() passing through  RTP ssrc=1267383257, seqnum=26835, ts=1430514213, streamHashCode=1590246027
JVB 2019-01-11 13:46:56.430 FINE: [42771] org.ice4j.stack.StunClientTransaction.sendRequest() sending STUN  tid 0x2BDEE13E6801AC45432DA308 from 192.168.1.99:14645/udp to 192.168.1.98:53180/udp
JVB 2019-01-11 13:46:56.431 FINE: [42638] org.jitsi.impl.neomedia.transform.srtp.SRTPCryptoContext.log() Reverse transform for SSRC 713663915 SeqNo=27204 s_l=27203 seqNumSet=true guessedROC=0 roc=0
JVB 2019-01-11 13:46:56.432 FINER: [42638] org.jitsi.impl.neomedia.rtp.RawPacketCache.log() Caching a packet. SSRC=713663915 seq=27204
JVB 2019-01-11 13:46:56.432 FINE: [42770] org.ice4j.stack.StunClientTransaction.sendRequest() sending STUN  tid 0x2FDEE13E6801AD719E3E50A9 from 192.168.1.99:14645/udp to 192.168.1.98:53180/udp
JVB 2019-01-11 13:46:56.432 FINEST: [42593] org.ice4j.stack.Connector.run() received datagram packet - addr: /192.168.1.98 port: 53180
JVB 2019-01-11 13:46:56.432 FINEST: [42590] org.ice4j.stack.MessageProcessor.run() Dispatching a StunMessageEvent.
JVB 2019-01-11 13:46:56.432 FINEST: [42590] org.ice4j.stack.StunStack.handleMessageEvent() Received a message on 192.168.1.99:14645/udp of type:257
JVB 2019-01-11 13:46:56.432 FINE: [42590] org.ice4j.stack.StunClientTransaction.handleResponse() handleResponse tid 0x2BDEE13E6801AC45432DA308
JVB 2019-01-11 13:46:56.442 INFO: [42590] org.ice4j.ice.ConnectivityCheckClient.log() IsControlling: true USE-CANDIDATE:true. Local ufrag 50ete1d0ve2stg
JVB 2019-01-11 13:46:56.443 INFO: [42590] org.ice4j.ice.ConnectivityCheckClient.log() Nomination confirmed for pair: 192.168.1.99:14645/udp/host -> 192.168.1.98:53180/udp/prflx (stream.RTP). Loal ufrag 50ete1d0ve2stg
JVB 2019-01-11 13:46:56.443 FINE: [42772] org.ice4j.stack.StunClientTransaction.sendRequest() sending STUN  tid 0x3BDEE13E6801C246A06AB1B0 from 192.168.1.99:14647/udp to 192.168.1.98:63550/udp
JVB 2019-01-11 13:46:56.444 FINEST: [42593] org.ice4j.stack.Connector.run() received datagram packet - addr: /192.168.1.98 port: 53180
JVB 2019-01-11 13:46:56.444 FINEST: [42591] org.ice4j.stack.MessageProcessor.run() Dispatching a StunMessageEvent.
JVB 2019-01-11 13:46:56.444 FINEST: [42591] org.ice4j.stack.StunStack.handleMessageEvent() Received a message on 192.168.1.99:14645/udp of type:257
JVB 2019-01-11 13:46:56.444 FINE: [42591] org.ice4j.stack.StunClientTransaction.handleResponse() handleResponse tid 0x2FDEE13E6801AD719E3E50A9
JVB 2019-01-11 13:46:56.448 FINEST: [42601] org.ice4j.stack.Connector.run() received datagram packet - addr: /192.168.1.98 port: 63550
JVB 2019-01-11 13:46:56.448 FINEST: [42600] org.ice4j.stack.MessageProcessor.run() Dispatching a StunMessageEvent.
JVB 2019-01-11 13:46:56.448 FINEST: [42600] org.ice4j.stack.StunStack.handleMessageEvent() Received a message on 192.168.1.99:14647/udp of type:257
JVB 2019-01-11 13:46:56.448 FINE: [42600] org.ice4j.stack.StunClientTransaction.handleResponse() handleResponse tid 0x3BDEE13E6801C246A06AB1B0
JVB 2019-01-11 13:46:56.452 INFO: [42600] org.ice4j.ice.ConnectivityCheckClient.log() Pair succeeded: 192.168.1.99:14647/udp/host -> 192.168.1.98:63550/udp/prflx (stream.RTP). Local ufrag 21apm1d0ve2sts
JVB 2019-01-11 13:46:56.452 INFO: [42600] org.ice4j.socket.MergingDatagramSocket.log() Adding allowed address: 192.168.1.98:63550/udp
JVB 2019-01-11 13:46:56.453 INFO: [42600] org.ice4j.ice.ConnectivityCheckClient.log() Pair validated: 192.168.1.99:14647/udp/host -> 192.168.1.98:63550/udp/prflx (stream.RTP). Local ufrag 21apm1d0ve2sts
JVB 2019-01-11 13:46:56.453 INFO: [42600] org.ice4j.ice.DefaultNominator.log() Nominate (first valid): 192.168.1.99:14647/udp/host -> 192.168.1.98:63550/udp/prflx (stream.RTP). Local ufrag 21apm1d0ve2sts
JVB 2019-01-11 13:46:56.453 FINE: [42638] org.jitsi.impl.neomedia.transform.srtp.SRTPCryptoContext.log() Reverse transform for SSRC 713663915 SeqNo=27206 s_l=27205 seqNumSet=true guessedROC=0 roc=0
JVB 2019-01-11 13:46:56.453 FINE: [42627] org.jitsi.impl.neomedia.transform.srtp.SRTPCryptoContext.log() Reverse transform for SSRC 1267383257 SeqNo=26836 s_l=26835 seqNumSet=true guessedROC=0 roc=0
JVB 2019-01-11 13:46:56.454 FINE: [42627] org.jitsi.impl.neomedia.transform.DiscardTransformEngine.log() passing through  RTP ssrc=1267383257, seqnum=26836, ts=1430515173, streamHashCode=1590246027
JVB 2019-01-11 13:46:56.455 INFO: [42590] org.ice4j.ice.CheckList.log() Selected pair for stream stream.RTP: 192.168.1.99:14645/udp/host -> 192.168.1.98:53180/udp/prflx (stream.RTP)
JVB 2019-01-11 13:46:57.327 FINEST: [42601] org.ice4j.stack.Connector.run() received datagram packet - addr: /192.168.1.98 port: 63550
JVB 2019-01-11 13:46:57.327 FINEST: [42600] org.ice4j.stack.MessageProcessor.run() Dispatching a StunMessageEvent.
JVB 2019-01-11 13:46:57.327 FINEST: [42600] org.ice4j.stack.StunStack.handleMessageEvent() Received a message on 192.168.1.99:14647/udp of type:1
JVB 2019-01-11 13:46:57.327 FINEST: [42600] org.ice4j.stack.StunStack.handleMessageEvent() parsing request
JVB 2019-01-11 13:46:57.327 FINEST: [42600] org.ice4j.stack.StunStack.handleMessageEvent() existing transaction not found
JVB 2019-01-11 13:46:57.328 FINEST: [42593] org.ice4j.stack.Connector.run() received datagram packet - addr: /192.168.1.98 port: 53180
JVB 2019-01-11 13:46:57.328 FINE: [42627] org.jitsi.impl.neomedia.transform.srtp.SRTPCryptoContext.log() Reverse transform for SSRC 1267383257 SeqNo=26880 s_l=26879 seqNumSet=true guessedROC=0 roc=0
JVB 2019-01-11 13:46:57.328 FINE: [42627] org.jitsi.impl.neomedia.transform.DiscardTransformEngine.log() passing through  RTP ssrc=1267383257, seqnum=26880, ts=1430557413, streamHashCode=1590246027
JVB 2019-01-11 13:46:57.329 FINEST: [42592] org.ice4j.stack.MessageProcessor.run() Dispatching a StunMessageEvent.
JVB 2019-01-11 13:46:57.329 FINEST: [42592] org.ice4j.stack.StunStack.handleMessageEvent() Received a message on 192.168.1.99:14645/udp of type:1
JVB 2019-01-11 13:46:57.329 FINEST: [42592] org.ice4j.stack.StunStack.handleMessageEvent() parsing request
JVB 2019-01-11 13:46:57.329 FINEST: [42592] org.ice4j.stack.StunStack.handleMessageEvent() existing transaction not found
JVB 2019-01-11 13:46:57.329 FINEST: [42592] org.ice4j.stack.StunStack.validateMessageIntegrity() Successfully verified msg integrity
JVB 2019-01-11 13:47:01.346 FINEST: [42601] org.ice4j.stack.Connector.run() received datagram packet - addr: /192.168.1.98 port: 63550
JVB 2019-01-11 13:47:01.346 FINEST: [42598] org.ice4j.stack.MessageProcessor.run() Dispatching a StunMessageEvent.
JVB 2019-01-11 13:47:01.346 FINEST: [42598] org.ice4j.stack.StunStack.handleMessageEvent() Received a message on 192.168.1.99:14647/udp of type:1
JVB 2019-01-11 13:47:01.347 FINEST: [42598] org.ice4j.stack.StunStack.handleMessageEvent() parsing request
JVB 2019-01-11 13:47:01.347 FINEST: [42598] org.ice4j.stack.StunStack.handleMessageEvent() existing transaction not found
JVB 2019-01-11 13:47:01.347 FINE: [42627] org.jitsi.impl.neomedia.transform.srtp.SRTPCryptoContext.log() Reverse transform for SSRC 1267383257 SeqNo=27081 s_l=27080 seqNumSet=true guessedROC=0 roc=0
JVB 2019-01-11 13:47:01.347 FINEST: [42598] org.ice4j.stack.StunStack.validateMessageIntegrity() Successfully verified msg integrity
JVB 2019-01-11 13:47:01.347 FINEST: [42593] org.ice4j.stack.Connector.run() received datagram packet - addr: /192.168.1.98 port: 53180
JVB 2019-01-11 13:47:01.347 FINE: [42627] org.jitsi.impl.neomedia.transform.DiscardTransformEngine.log() passing through  RTP ssrc=1267383257, seqnum=27081, ts=1430750373, streamHashCode=1590246027
JVB 2019-01-11 13:47:01.348 FINEST: [42591] org.ice4j.stack.MessageProcessor.run() Dispatching a StunMessageEvent.
JVB 2019-01-11 13:47:01.348 FINEST: [42591] org.ice4j.stack.StunStack.handleMessageEvent() Received a message on 192.168.1.99:14645/udp of type:1
JVB 2019-01-11 13:47:01.348 FINEST: [42591] org.ice4j.stack.StunStack.handleMessageEvent() parsing request
JVB 2019-01-11 13:47:01.348 FINEST: [42591] org.ice4j.stack.StunStack.handleMessageEvent() existing transaction not found
JVB 2019-01-11 13:47:01.348 FINEST: [42591] org.ice4j.stack.StunStack.validateMessageIntegrity() Successfully verified msg integrity
JVB 2019-01-11 13:47:01.350 FINEST: [42625] net.sf.fmj.media.rtp.RTCPReporter.run() RTCP reporting for running again after 2684.6611055266626 ms.
JVB 2019-01-11 13:47:01.465 INFO: [42775] org.ice4j.ice.ConnectivityCheckClient.log() CheckList for stream stream FAILED
JVB 2019-01-11 13:47:01.465 INFO: [42775] org.ice4j.ice.Agent.log() Suspicious ICE connectivity failure. Checks failed but the remote end was able to reach us.
JVB 2019-01-11 13:47:01.465 INFO: [42775] org.ice4j.ice.Agent.log() ICE state is FAILED
JVB 2019-01-11 13:47:01.465 INFO: [42775] org.ice4j.ice.Agent.log() ICE state changed from Running to Failed. Local ufrag 50ete1d0ve2stg

Any advice on how to debug this further would be appreciated.


Enable Aggressive Candidate Nomination