JVB not establishing connection to public client IP

Dear Community,

Our office ran into a problem with our jitsi-meet instance today. The setup is as follows (anonymized):

Jitsi-meet running on Ubuntu 20.04. The server has it’s own public IP (1.2.3.4) and domain (https://www.our-office.com) as well as a VPN-Interface (10.80.254.4) that connects it directly to our office.

When trying to facilitate a video conference with a couple of other offices today we got the feedback that it worked horribly. Upon digging into the logs I’ve found that when one of the outside participants tried to join, the videobridge attempted to find a working ICE pair, but it looks like it only ever tried the remote participants internal subnet IP (10.1.10.189). The remote participants public IP (9.9.9.9, gathered from webserver access logs) never once appears in the jvb log. The following block from the jvb.log reflects this:

2020-11-12 13:33:27.387 INFO: [38] [confId=b4e5988f7f2b4e48 epId=7cf80311 local_ufrag=d5onu1emu74hqr gid=2329 conf_name=test@conference.meet.our-office.com ufrag=d5onu1emu74hqr] Agent.gatherCandidates#622: Gathering candidates for component stream-7cf80311.RTP.
2020-11-12 13:33:27.389 INFO: [38] [confId=b4e5988f7f2b4e48 epId=7cf80311 gid=2329 conf_name=test@conference.meet.our-office.com] Endpoint.lambda$setTransportInfo$11#1048: Ignoring empty DtlsFingerprint extension: <transport xmlns='urn:xmpp:jingle:transports:ice-udp:1'><fingerprint xmlns='urn:xmpp:jingle:apps:dtls:0' required='false'/></transport>
2020-11-12 13:33:27.944 INFO: [38] [confId=b4e5988f7f2b4e48 epId=7cf80311 gid=2329 stats_id=Gwendolyn-KsO conf_name=test@conference.meet.our-office.com] DtlsTransport.setSetupAttribute#120: The remote side is acting as DTLS client, we'll act as server
2020-11-12 13:33:27.944 INFO: [38] [confId=b4e5988f7f2b4e48 epId=7cf80311 local_ufrag=d5onu1emu74hqr gid=2329 stats_id=Gwendolyn-KsO conf_name=test@conference.meet.our-office.com] IceTransport.startConnectivityEstablishment#182: Starting the Agent without remote candidates.
2020-11-12 13:33:27.944 INFO: [38] [confId=b4e5988f7f2b4e48 gid=2329 stats_id=Gwendolyn-KsO conf_name=test@conference.meet.our-office.com ufrag=d5onu1emu74hqr epId=7cf80311 local_ufrag=d5onu1emu74hqr] Agent.startConnectivityEstablishment#713: Start ICE connectivity establishment.
2020-11-12 13:33:27.944 INFO: [38] [confId=b4e5988f7f2b4e48 gid=2329 stats_id=Gwendolyn-KsO conf_name=test@conference.meet.our-office.com ufrag=d5onu1emu74hqr epId=7cf80311 local_ufrag=d5onu1emu74hqr] Agent.initCheckLists#949: Init checklist for stream stream-7cf80311
2020-11-12 13:33:27.944 INFO: [38] [confId=b4e5988f7f2b4e48 gid=2329 stats_id=Gwendolyn-KsO conf_name=test@conference.meet.our-office.com ufrag=d5onu1emu74hqr epId=7cf80311 local_ufrag=d5onu1emu74hqr] Agent.setState#923: ICE state changed from Waiting to Running.
2020-11-12 13:33:27.945 INFO: [38] [confId=b4e5988f7f2b4e48 epId=7cf80311 local_ufrag=d5onu1emu74hqr gid=2329 stats_id=Gwendolyn-KsO conf_name=test@conference.meet.our-office.com] IceTransport.iceStateChanged#321: ICE state changed old=Waiting new=Running
2020-11-12 13:33:27.945 INFO: [38] [confId=b4e5988f7f2b4e48 gid=2329 stats_id=Gwendolyn-KsO conf_name=test@conference.meet.our-office.com ufrag=d5onu1emu74hqr epId=7cf80311 local_ufrag=d5onu1emu74hqr] ConnectivityCheckClient.startChecks#142: Start connectivity checks.
2020-11-12 13:33:27.946 INFO: [38] [confId=b4e5988f7f2b4e48 gid=2329 stats_id=Gwendolyn-KsO componentId=1 conf_name=test@conference.meet.our-office.com ufrag=d5onu1emu74hqr name=stream-7cf80311 epId=7cf80311 local_ufrag=d5onu1emu74hqr] Component.addUpdateRemoteCandidates#347: Update remote candidate for stream-7cf80311.RTP: 10.1.10.189:55076/udp
2020-11-12 13:33:27.946 INFO: [38] [confId=b4e5988f7f2b4e48 gid=2329 stats_id=Gwendolyn-KsO componentId=1 conf_name=test@conference.meet.our-office.com ufrag=d5onu1emu74hqr name=stream-7cf80311 epId=7cf80311 local_ufrag=d5onu1emu74hqr] Component.updateRemoteCandidates#481: new Pair added: 10.80.254.4:10000/udp/host -> 10.1.10.189:55076/udp/host (stream-7cf80311.RTP).
2020-11-12 13:33:27.946 INFO: [38] [confId=b4e5988f7f2b4e48 gid=2329 stats_id=Gwendolyn-KsO componentId=1 conf_name=test@conference.meet.our-office.com ufrag=d5onu1emu74hqr name=stream-7cf80311 epId=7cf80311 local_ufrag=d5onu1emu74hqr] Component.updateRemoteCandidates#481: new Pair added: 1.2.3.4:10000/udp/host -> 10.1.10.189:55076/udp/host (stream-7cf80311.RTP).
2020-11-12 13:33:27.947 INFO: [38] [confId=b4e5988f7f2b4e48 gid=2329 stats_id=Gwendolyn-KsO componentId=1 conf_name=test@conference.meet.our-office.com ufrag=d5onu1emu74hqr name=stream-7cf80311 epId=7cf80311 local_ufrag=d5onu1emu74hqr] Component.addUpdateRemoteCandidates#347: Update remote candidate for stream-7cf80311.RTP: 10.1.10.189:55076/udp
2020-11-12 13:33:27.947 INFO: [38] [confId=b4e5988f7f2b4e48 gid=2329 stats_id=Gwendolyn-KsO componentId=1 conf_name=test@conference.meet.our-office.com ufrag=d5onu1emu74hqr name=stream-7cf80311 epId=7cf80311 local_ufrag=d5onu1emu74hqr] Component.addUpdateRemoteCandidates#369: Not adding duplicate remote candidate: 10.1.10.189:55076/udp
2020-11-12 13:33:27.965 INFO: [251480] [confId=b4e5988f7f2b4e48 gid=2329 stats_id=Gwendolyn-KsO conf_name=test@conference.meet.our-office.com ufrag=d5onu1emu74hqr epId=7cf80311 local_ufrag=d5onu1emu74hqr] ConnectivityCheckClient$PaceMaker.run#922: Pair failed: 10.80.254.4:10000/udp/host -> 10.1.10.189:55076/udp/host (stream-7cf80311.RTP)
2020-11-12 13:33:27.986 INFO: [251480] [confId=b4e5988f7f2b4e48 gid=2329 stats_id=Gwendolyn-KsO conf_name=test@conference.meet.our-office.com ufrag=d5onu1emu74hqr epId=7cf80311 local_ufrag=d5onu1emu74hqr] ConnectivityCheckClient$PaceMaker.run#922: Pair failed: 1.2.3.4:10000/udp/host -> 10.1.10.189:55076/udp/host (stream-7cf80311.RTP)
2020-11-12 13:33:45.039 INFO: [38] [confId=b4e5988f7f2b4e48 epId=7cf80311 gid=2329 stats_id=Gwendolyn-KsO conf_name=test@conference.meet.our-office.com] AbstractEndpoint.expire#233: Expiring.
2020-11-12 13:33:45.040 INFO: [38] [confId=b4e5988f7f2b4e48 epId=7cf80311 gid=2329 stats_id=Gwendolyn-KsO conf_name=test@conference.meet.our-office.com] Transceiver.teardown#319: Tearing down
2020-11-12 13:33:45.040 INFO: [38] [confId=b4e5988f7f2b4e48 epId=7cf80311 gid=2329 stats_id=Gwendolyn-KsO conf_name=test@conference.meet.our-office.com] RtpReceiverImpl.tearDown#313: Tearing down
2020-11-12 13:33:45.040 INFO: [38] [confId=b4e5988f7f2b4e48 epId=7cf80311 gid=2329 stats_id=Gwendolyn-KsO conf_name=test@conference.meet.our-office.com] RtpSenderImpl.tearDown#288: Tearing down
2020-11-12 13:33:45.040 INFO: [38] [confId=b4e5988f7f2b4e48 epId=7cf80311 gid=2329 stats_id=Gwendolyn-KsO conf_name=test@conference.meet.our-office.com] DtlsTransport.stop#184: Stopping
2020-11-12 13:33:45.040 INFO: [38] [confId=b4e5988f7f2b4e48 epId=7cf80311 local_ufrag=d5onu1emu74hqr gid=2329 stats_id=Gwendolyn-KsO conf_name=test@conference.meet.our-office.com] IceTransport.stop#235: Stopping
2020-11-12 13:33:45.040 INFO: [38] [confId=b4e5988f7f2b4e48 gid=2329 stats_id=Gwendolyn-KsO conf_name=test@conference.meet.our-office.com ufrag=d5onu1emu74hqr epId=7cf80311 local_ufrag=d5onu1emu74hqr] Agent.setState#923: ICE state changed from Running to Terminated.
2020-11-12 13:33:45.041 INFO: [38] [confId=b4e5988f7f2b4e48 epId=7cf80311 local_ufrag=d5onu1emu74hqr gid=2329 stats_id=Gwendolyn-KsO conf_name=test@conference.meet.our-office.com] IceTransport.iceStateChanged#321: ICE state changed old=Running new=Terminated
2020-11-12 13:33:45.041 INFO: [38] [confId=b4e5988f7f2b4e48 gid=2329 stats_id=Gwendolyn-KsO componentId=1 conf_name=test@conference.meet.our-office.com ufrag=d5onu1emu74hqr name=stream-7cf80311 epId=7cf80311 local_ufrag=d5onu1emu74hqr] MergingDatagramSocket.close#142: Closing.
2020-11-12 13:33:45.041 INFO: [38] [confId=b4e5988f7f2b4e48 epId=7cf80311 gid=2329 stats_id=Gwendolyn-KsO conf_name=test@conference.meet.our-office.com] Endpoint.expire#782: Expired.

After this sequence happens a couple of times, the logs show the following repeteadly:

2020-11-12 13:34:29.001 WARNING: [251482] [confId=b4e5988f7f2b4e48 epId=70b2b4a8 gid=2329 stats_id=Everette-at2 conf_name=test@conference.meet.our-office.com] EndpointMessageTransport.endpointMessage#574: Unable to find endpoint to send EndpointMessage to: 7cf80311
2020-11-12 13:34:39.001 WARNING: [251482] [confId=b4e5988f7f2b4e48 epId=70b2b4a8 gid=2329 stats_id=Everette-at2 conf_name=test@conference.meet.our-office.com] EndpointMessageTransport.endpointMessage#574: Unable to find endpoint to send EndpointMessage to: 7cf80311
2020-11-12 13:34:49.001 WARNING: [251466] [confId=b4e5988f7f2b4e48 epId=70b2b4a8 gid=2329 stats_id=Everette-at2 conf_name=test@conference.meet.our-office.com] EndpointMessageTransport.endpointMessage#574: Unable to find endpoint to send EndpointMessage to: 7cf80311
2020-11-12 13:34:59.006 WARNING: [251482] [confId=b4e5988f7f2b4e48 epId=70b2b4a8 gid=2329 stats_id=Everette-at2 conf_name=test@conference.meet.our-office.com] EndpointMessageTransport.endpointMessage#574: Unable to find endpoint to send EndpointMessage to: 7cf80311
2020-11-12 13:35:09.003 WARNING: [251482] [confId=b4e5988f7f2b4e48 epId=70b2b4a8 gid=2329 stats_id=Everette-at2 conf_name=test@conference.meet.our-office.com] EndpointMessageTransport.endpointMessage#574: Unable to find endpoint to send EndpointMessage to: 7cf80311

What could be the reason that jvb doesn’t even add a candidate pair for 1.2.3.4 <=> 9.9.9.9 ?
With a different remote participant in the same conference the logs show that jvb was able to establish a connection between its public IP and the remote public IP without a problem.

Regards,
Mo

It may be the client did not discover it through stun as udp is blocked in its network or the stun requests were blocked. On this occasions it should fallback to the turns, the turnserver, and relay from there using TCP.