ICE harvester of JVB2 don't recognize public address of clients

In my installation, the ICE harvester of JVB2 don’t list the public IP adress of a client as a candidate for the data connections. This don’t happen at all before using JVB1.

I’m using Openfire with it’s OpenMeet plugin, which is currently switching from JVB1 to JVB2 because of the well-known TLS-“version-cut” of the common clients.

I already successful changed the components and most things like JiFoCo already seems to work. But using external clients, the ICE harvester don’t sample candidates for the public IP addresses of the client; it just list the local ones - this can’t be used to establish the A/V-connections of course.

This don’t happens with JVB1, all of the environment at the server side is unchanged. The server have a well-known static IP, there’s a static translation to a DMZ transfer net at the firewall.

Please explain in what way the client public is detected: What’s the actor and the source. This may help me to understand what’s happens and what’s fail now.

JVB2, harvesting of client public address is not working:

20201123-161957.284 INFO  [Thread-91] [o.j.o.p.o.JvbPluginWrapper] 2020-11-23 16:19:57.284 INFO: [30] [confId=2c866991c3838e9d epId=156786ab local_ufrag=2qacv1enqr19r6 gid=35185 stats_id=Adah-rAB conf_name=gurkensalat@conference.eval.xmpp.dnb.de] IceTransport.iceStateChanged#323: ICE state changed old=Waiting new=Running
20201123-161957.284 INFO  [Thread-91] [o.j.o.p.o.JvbPluginWrapper] 2020-11-23 16:19:57.284 INFO: [30] [confId=2c866991c3838e9d gid=35185 stats_id=Adah-rAB conf_name=gurkensalat@conference.eval.xmpp.dnb.de ufrag=2qacv1enqr19r6 epId=156786ab local_ufrag=2qacv1enqr19r6] ConnectivityCheckClient.startChecks#142: Start connectivity checks.
20201123-161957.296 INFO  [Thread-91] [o.j.o.p.o.JvbPluginWrapper] 2020-11-23 16:19:57.296 INFO: [30] [confId=2c866991c3838e9d gid=35185 stats_id=Adah-rAB componentId=1 conf_name=gurkensalat@conference.eval.xmpp.dnb.de ufrag=2qacv1enqr19r6 name=stream-156786ab epId=156786ab local_ufrag=2qacv1enqr19r6] Component.addUpdateRemoteCandidates#347: Update remote candidate for stream-156786ab.RTP: 172.16.2.17:34056/udp
20201123-161957.297 INFO  [Thread-91] [o.j.o.p.o.JvbPluginWrapper] 2020-11-23 16:19:57.297 INFO: [30] [confId=2c866991c3838e9d gid=35185 stats_id=Adah-rAB componentId=1 conf_name=gurkensalat@conference.eval.xmpp.dnb.de ufrag=2qacv1enqr19r6 name=stream-156786ab epId=156786ab local_ufrag=2qacv1enqr19r6] Component.updateRemoteCandidates#481: new Pair added: 10.10.1.141:10000/udp/host -> 172.16.2.17:34056/udp/host (stream-156786ab.RTP).
20201123-161957.297 INFO  [Thread-91] [o.j.o.p.o.JvbPluginWrapper] 2020-11-23 16:19:57.297 INFO: [30] [confId=2c866991c3838e9d gid=35185 stats_id=Adah-rAB componentId=1 conf_name=gurkensalat@conference.eval.xmpp.dnb.de ufrag=2qacv1enqr19r6 name=stream-156786ab epId=156786ab local_ufrag=2qacv1enqr19r6] Component.updateRemoteCandidates#481: new Pair added: 10.10.59.52:10000/udp/host -> 172.16.2.17:34056/udp/host (stream-156786ab.RTP).
20201123-161957.298 INFO  [Thread-91] [o.j.o.p.o.JvbPluginWrapper] 2020-11-23 16:19:57.297 INFO: [30] [confId=2c866991c3838e9d gid=35185 stats_id=Adah-rAB componentId=1 conf_name=gurkensalat@conference.eval.xmpp.dnb.de ufrag=adl801enqr1aco name=stream-f3a3ba17 epId=f3a3ba17 local_ufrag=adl801enqr1aco] Component.addUpdateRemoteCandidates#347: Update remote candidate for stream-f3a3ba17.RTP: 172.16.2.17:47180/udp
20201123-161957.298 INFO  [Thread-91] [o.j.o.p.o.JvbPluginWrapper] 2020-11-23 16:19:57.298 INFO: [30] [confId=2c866991c3838e9d gid=35185 stats_id=Adah-rAB componentId=1 conf_name=gurkensalat@conference.eval.xmpp.dnb.de ufrag=adl801enqr1aco name=stream-f3a3ba17 epId=f3a3ba17 local_ufrag=adl801enqr1aco] Component.updateRemoteCandidates#481: new Pair added: 10.10.1.141:10000/udp/host -> 172.16.2.17:47180/udp/host (stream-f3a3ba17.RTP).
20201123-161957.298 INFO  [Thread-91] [o.j.o.p.o.JvbPluginWrapper] 2020-11-23 16:19:57.298 INFO: [30] [confId=2c866991c3838e9d gid=35185 stats_id=Adah-rAB componentId=1 conf_name=gurkensalat@conference.eval.xmpp.dnb.de ufrag=adl801enqr1aco name=stream-f3a3ba17 epId=f3a3ba17 local_ufrag=adl801enqr1aco] Component.updateRemoteCandidates#481: new Pair added: 10.10.59.52:10000/udp/host -> 172.16.2.17:47180/udp/host (stream-f3a3ba17.RTP).
20201123-161957.311 INFO  [Thread-91] [o.j.o.p.o.JvbPluginWrapper] 2020-11-23 16:19:57.311 INFO: [37] [confId=2c866991c3838e9d gid=35185 stats_id=Adah-rAB conf_name=gurkensalat@conference.eval.xmpp.dnb.de ufrag=2qacv1enqr19r6 epId=156786ab local_ufrag=2qacv1enqr19r6] ConnectivityCheckClient$PaceMaker.run#922: Pair failed: 10.10.1.141:10000/udp/host -> 172.16.2.17:34056/udp/host (stream-156786ab.RTP)
20201123-161957.311 INFO  [Thread-91] [o.j.o.p.o.JvbPluginWrapper] 2020-11-23 16:19:57.311 INFO: [36] [confId=2c866991c3838e9d gid=35185 stats_id=Adah-rAB conf_name=gurkensalat@conference.eval.xmpp.dnb.de ufrag=adl801enqr1aco epId=f3a3ba17 local_ufrag=adl801enqr1aco] ConnectivityCheckClient$PaceMaker.run#922: Pair failed: 10.10.1.141:10000/udp/host -> 172.16.2.17:47180/udp/host (stream-f3a3ba17.RTP)
20201123-161957.332 INFO  [Thread-91] [o.j.o.p.o.JvbPluginWrapper] 2020-11-23 16:19:57.332 INFO: [37] [confId=2c866991c3838e9d gid=35185 stats_id=Adah-rAB conf_name=gurkensalat@conference.eval.xmpp.dnb.de ufrag=adl801enqr1aco epId=f3a3ba17 local_ufrag=adl801enqr1aco] ConnectivityCheckClient$PaceMaker.run#922: Pair failed: 10.10.59.52:10000/udp/host -> 172.16.2.17:47180/udp/host (stream-f3a3ba17.RTP)
20201123-161957.332 INFO  [Thread-91] [o.j.o.p.o.JvbPluginWrapper] 2020-11-23 16:19:57.332 INFO: [36] [confId=2c866991c3838e9d gid=35185 stats_id=Adah-rAB conf_name=gurkensalat@conference.eval.xmpp.dnb.de ufrag=2qacv1enqr19r6 epId=156786ab local_ufrag=2qacv1enqr19r6] ConnectivityCheckClient$PaceMaker.run#922: Pair failed: 10.10.59.52:10000/udp/host -> 172.16.2.17:34056/udp/host (stream-156786ab.RTP)
20201123-161957.403 INFO  [Thread-91] [o.j.o.p.o.JvbPluginWrapper] 2020-11-23 16:19:57.403 INFO: [30] [confId=2c866991c3838e9d gid=35185 stats_id=Adah-rAB componentId=1 conf_name=gurkensalat@conference.eval.xmpp.dnb.de ufrag=2qacv1enqr19r6 name=stream-156786ab epId=156786ab local_ufrag=2qacv1enqr19r6] Component.addUpdateRemoteCandidates#347: Update remote candidate for stream-156786ab.RTP: 172.16.2.17:34056/udp
20201123-161957.403 INFO  [Thread-91] [o.j.o.p.o.JvbPluginWrapper] 2020-11-23 16:19:57.403 INFO: [30] [confId=2c866991c3838e9d gid=35185 stats_id=Adah-rAB componentId=1 conf_name=gurkensalat@conference.eval.xmpp.dnb.de ufrag=2qacv1enqr19r6 name=stream-156786ab epId=156786ab local_ufrag=2qacv1enqr19r6] Component.addUpdateRemoteCandidates#369: Not adding duplicate remote candidate: 172.16.2.17:34056/udp
20201123-161957.405 INFO  [Thread-91] [o.j.o.p.o.JvbPluginWrapper] 2020-11-23 16:19:57.405 INFO: [30] [confId=2c866991c3838e9d gid=35185 stats_id=Adah-rAB componentId=1 conf_name=gurkensalat@conference.eval.xmpp.dnb.de ufrag=adl801enqr1aco name=stream-f3a3ba17 epId=f3a3ba17 local_ufrag=adl801enqr1aco] Component.addUpdateRemoteCandidates#347: Update remote candidate for stream-f3a3ba17.RTP: 172.16.2.17:47180/udp
20201123-161957.405 INFO  [Thread-91] [o.j.o.p.o.JvbPluginWrapper] 2020-11-23 16:19:57.405 INFO: [30] [confId=2c866991c3838e9d gid=35185 stats_id=Adah-rAB componentId=1 conf_name=gurkensalat@conference.eval.xmpp.dnb.de ufrag=adl801enqr1aco name=stream-f3a3ba17 epId=f3a3ba17 local_ufrag=adl801enqr1aco] Component.addUpdateRemoteCandidates#369: Not adding duplicate remote candidate: 172.16.2.17:47180/udp```

JVB1; harvesting of client public address is working:
20201123-194246.138 INFO  [pool-9-thread-2] [o.i.i.ConnectivityCheckClient] Start connectivity checks. Local ufrag 1djgb1enr6klbu
20201123-194246.175 INFO  [etAccessManager-pool-17-thread-1] [o.i.i.ConnectivityCheckClient] Pair succeeded: 10.10.1.137:10000/udp/host -> 87.144.250.254:34892/udp/prflx (stream.RTP). Local ufrag 1djgb1enr6klbu
20201123-194246.179 INFO  [etAccessManager-pool-17-thread-1] [o.i.s.MergingDatagramSocket] Adding allowed address: 87.144.250.254:34892/udp
20201123-194246.179 INFO  [etAccessManager-pool-17-thread-1] [o.i.i.ConnectivityCheckClient] Pair validated: 193.175.100.137:10000/udp/srflx -> 87.144.250.254:34892/udp/prflx (stream.RTP). Local ufrag 1djgb1enr6klbu
20201123-194246.180 INFO  [etAccessManager-pool-17-thread-2] [o.i.i.ConnectivityCheckClient] Pair succeeded: 10.10.1.137:10000/udp/host -> 87.144.250.254:34892/udp/prflx (stream.RTP). Local ufrag 1djgb1enr6klbu
20201123-194246.180 INFO  [etAccessManager-pool-17-thread-2] [o.i.i.ConnectivityCheckClient] Pair validated: 193.175.100.137:10000/udp/srflx -> 87.144.250.254:34892/udp/prflx (stream.RTP). Local ufrag 1djgb1enr6klbu
20201123-194246.182 INFO  [etAccessManager-pool-17-thread-1] [o.i.i.DefaultNominator] Nominate (first valid): 193.175.100.137:10000/udp/srflx -> 87.144.250.254:34892/udp/prflx (stream.RTP). Local ufrag 1djgb1enr6klbu
20201123-194246.183 INFO  [etAccessManager-pool-17-thread-1] [o.i.i.Agent] verify if nominated pair answer again
20201123-194246.183 INFO  [etAccessManager-pool-17-thread-1] [o.i.i.ConnectivityCheckClient] IsControlling: true USE-CANDIDATE:false. Local ufrag 1djgb1enr6klbu
20201123-194246.185 INFO  [etAccessManager-pool-17-thread-2] [o.i.i.DefaultNominator] Nominate (first valid): 193.175.100.137:10000/udp/srflx -> 87.144.250.254:34892/udp/prflx (stream.RTP). Local ufrag 1djgb1enr6klbu
20201123-194246.185 INFO  [etAccessManager-pool-17-thread-2] [o.i.i.ConnectivityCheckClient] IsControlling: true USE-CANDIDATE:false. Local ufrag 1djgb1enr6klbu
20201123-194246.188 INFO  [pool-9-thread-3] [o.i.i.Component] Update remote candidate for stream.RTP: 172.16.142.3:34892/udp
20201123-194246.189 INFO  [pool-9-thread-3] [o.i.i.Component] Update remote candidate for stream.RTP: 172.16.142.3:9/tcp
20201123-194246.189 INFO  [pool-9-thread-3] [o.i.i.Component] new Pair added: 10.10.1.137:4443/tcp/host -> 172.16.142.3:9/tcp/host (stream.RTP). Local ufrag 1djgb1enr6klbu
20201123-194246.190 INFO  [pool-9-thread-3] [o.i.i.Component] new Pair added: 10.10.61.52:4443/tcp/host -> 172.16.142.3:9/tcp/host (stream.RTP). Local ufrag 1djgb1enr6klbu
20201123-194246.190 INFO  [pool-9-thread-3] [o.i.i.Component] new Pair added: 10.10.1.137:10000/udp/host -> 172.16.142.3:34892/udp/host (stream.RTP). Local ufrag 1djgb1enr6klbu
20201123-194246.190 INFO  [pool-9-thread-3] [o.i.i.Component] new Pair added: 10.10.61.52:10000/udp/host -> 172.16.142.3:34892/udp/host (stream.RTP). Local ufrag 1djgb1enr6klbu
20201123-194246.190 INFO  [pool-9-thread-3] [o.i.i.Component] new Pair added: 193.175.100.137:4443/tcp/srflx -> 172.16.142.3:9/tcp/host (stream.RTP). Local ufrag 1djgb1enr6klbu
20201123-194246.190 INFO  [pool-9-thread-3] [o.i.i.Component] new Pair added: 193.175.100.137:10000/udp/srflx -> 172.16.142.3:34892/udp/host (stream.RTP). Local ufrag 1djgb1enr6klbu
20201123-194246.201 INFO  [.Agent-executor-pool-15-thread-1] [o.i.i.ConnectivityCheckClient] Pair failed: 10.10.1.137:10000/udp/host -> 172.16.142.3:34892/udp/host (stream.RTP)
20201123-194246.216 INFO  [etAccessManager-pool-17-thread-2] [o.i.i.ConnectivityCheckClient] Pair succeeded: 193.175.100.137:10000/udp/srflx -> 87.144.250.254:34892/udp/prflx (stream.RTP). Local ufrag 1djgb1enr6klbu
20201123-194246.217 INFO  [etAccessManager-pool-17-thread-2] [o.i.i.ConnectivityCheckClient] Pair validated: 193.175.100.137:10000/udp/srflx -> 87.144.250.254:34892/udp/prflx (stream.RTP). Local ufrag 1djgb1enr6klbu
20201123-194246.217 INFO  [etAccessManager-pool-17-thread-2] [o.i.i.DefaultNominator] Nominate (first valid): 193.175.100.137:10000/udp/srflx -> 87.144.250.254:34892/udp/prflx (stream.RTP). Local ufrag 1djgb1enr6klbu
20201123-194246.217 INFO  [etAccessManager-pool-17-thread-2] [o.i.i.ConnectivityCheckClient] IsControlling: true USE-CANDIDATE:true. Local ufrag 1djgb1enr6klbu
20201123-194246.217 INFO  [etAccessManager-pool-17-thread-2] [o.i.i.ConnectivityCheckClient] Nomination confirmed for pair: 193.175.100.137:10000/udp/srflx -> 87.144.250.254:34892/udp/prflx (stream.RTP). Loal ufrag 1djgb1enr6klbu
20201123-194246.219 INFO  [etAccessManager-pool-17-thread-2] [o.i.i.CheckList] Selected pair for stream stream.RTP: 193.175.100.137:10000/udp/srflx -> 87.144.250.254:34892/udp/prflx (stream.RTP)
20201123-194246.220 INFO  [etAccessManager-pool-17-thread-2] [o.i.i.Agent] CheckList of stream stream is COMPLETED
20201123-194246.220 INFO  [etAccessManager-pool-17-thread-2] [o.i.i.Agent] ICE state changed from Running to Completed. Local ufrag 1djgb1enr6klbu
Thanks for support

Guido

Guido

The problem is most likely due to the client not getting the correct candidates for the bridge. Can you include the SENT logs (or XMPP traffic from the bridge), so we can confirm?

Gladly, but please, tell me how what kind of logs. Or where to get the XMPP traffic (should I sniff something?).

Grep for “SENT”. You will need to send the following property in logging.properties to enable debug logs:
org.jitsi.videobridge.xmpp.XmppConnection.level=ALL

I’ll do, but not yet because of an scheduled event. Thank you for quick feedback!

May close: I got a new snapshot from development, and now harvesting working. The Dev told, that there seems to be some mixup of the old sip-communicator.properties and the self-generated HOCON-styled config.

There still some quality issues, but I can at least connect again with Chrome-86, again. And now I even able to use FireFox-83 to join a meeting!