Weird log in JVB.log - ice4j failure to bind

Install & Config
1

hi

all is working, but in the log i get this (knowing that the signeleportharvest is 10050):

JVB 2020-03-20 17:09:54.465 INFO: [38] org.ice4j.ice.harvest.HostCandidateHarvester.createDatagramSocket() Retrying a bind because of a failure to bind to address /myIP and port 10051 (Address al
ready in use (Bind failed))
JVB 2020-03-20 17:09:54.465 INFO: [38] org.ice4j.ice.harvest.HostCandidateHarvester.createDatagramSocket() Retrying a bind because of a failure to bind to address /MYIP.MYIP.MYIP.MYIP and port 10052 (Address al
ready in use (Bind failed))
JVB 2020-03-20 17:09:54.465 INFO: [38] org.ice4j.ice.harvest.HostCandidateHarvester.createDatagramSocket() Retrying a bind because of a failure to bind to address /MYIP.MYIP.MYIP.MYIP and port 10053 (Address al
ready in use (Bind failed))
JVB 2020-03-20 17:09:54.465 INFO: [38] org.ice4j.ice.harvest.HostCandidateHarvester.createDatagramSocket() Retrying a bind because of a failure to bind to address /MYIP.MYIP.MYIP.MYIP and port 10054 (Address al
ready in use (Bind failed))
JVB 2020-03-20 17:09:54.466 INFO: [38] org.ice4j.ice.harvest.HostCandidateHarvester.createDatagramSocket() Retrying a bind because of a failure to bind to address /MYIP.MYIP.MYIP.MYIP and port 10052 (Address al
ready in use (Bind failed))
JVB 2020-03-20 17:09:54.467 INFO: [38] org.ice4j.ice.harvest.HostCandidateHarvester.createDatagramSocket() Retrying a bind because of a failure to bind to address /MYIP.MYIP.MYIP.MYIP and port 10053 (Address al
ready in use (Bind failed))
JVB 2020-03-20 17:09:54.467 INFO: [38] org.ice4j.ice.harvest.HostCandidateHarvester.createDatagramSocket() Retrying a bind because of a failure to bind to address /MYIP.MYIP.MYIP.MYIP and port 10054 (Address al
ready in use (Bind failed))
JVB 2020-03-20 17:09:54.467 INFO: [38] org.ice4j.ice.harvest.HostCandidateHarvester.createDatagramSocket() Retrying a bind because of a failure to bind to address /MYIP.MYIP.MYIP.MYIP and port 10055 (Address al
ready in use (Bind failed))

any idea ?

2

Did you check what’s listening on those ports?

3 
 sudo netstat -tulpn | grep LISTEN
tcp        0      0 127.0.0.1:11000         0.0.0.0:*               LISTEN      1077/lookup-domain-
tcp        0      0 0.0.0.0:25              0.0.0.0:*               LISTEN      1198/master
tcp        0      0 127.0.0.1:953           0.0.0.0:*               LISTEN      779/named
tcp        0      0 0.0.0.0:5280            0.0.0.0:*               LISTEN      1226/lua5.2
tcp        0      0 0.0.0.0:20000           0.0.0.0:*               LISTEN      1262/perl
tcp        0      0 127.0.0.1:5347          0.0.0.0:*               LISTEN      1226/lua5.2
tcp        0      0 0.0.0.0:5222            0.0.0.0:*               LISTEN      1226/lua5.2
tcp        0      0 127.0.0.1:10023         0.0.0.0:*               LISTEN      603/postgrey --pidf
tcp        0      0 127.0.0.1:3306          0.0.0.0:*               LISTEN      900/mysqld
tcp        0      0 0.0.0.0:587             0.0.0.0:*               LISTEN      1198/master
tcp        0      0 0.0.0.0:9999            0.0.0.0:*               LISTEN      1316/perl
tcp        0      0 0.0.0.0:465             0.0.0.0:*               LISTEN      1198/master
tcp        0      0 0.0.0.0:5269            0.0.0.0:*               LISTEN      1226/lua5.2
tcp        0      0 MYIP.MYIP.MYIP.MYIP:53       0.0.0.0:*               LISTEN      779/named
tcp        0      0 127.0.0.1:53            0.0.0.0:*               LISTEN      779/named
tcp        0      0 0.0.0.0:22              0.0.0.0:*               LISTEN      795/sshd
tcp6       0      0 :::8888                 :::*                    LISTEN      489/java
tcp6       0      0 :::25                   :::*                    LISTEN      1198/master
tcp6       0      0 ::1:953                 :::*                    LISTEN      779/named
tcp6       0      0 MYIP.MYIP.MYIP.MYIP:4443     :::*                    LISTEN      756/java
tcp6       0      0 :::443                  :::*                    LISTEN      1078/apache2
tcp6       0      0 :::5280                 :::*                    LISTEN      1226/lua5.2
tcp6       0      0 ::1:5347                :::*                    LISTEN      1226/lua5.2
tcp6       0      0 :::5222                 :::*                    LISTEN      1226/lua5.2
tcp6       0      0 :::587                  :::*                    LISTEN      1198/master
tcp6       0      0 :::9999                 :::*                    LISTEN      1316/perl
tcp6       0      0 :::8080                 :::*                    LISTEN      756/java
tcp6       0      0 :::80                   :::*                    LISTEN      1078/apache2
tcp6       0      0 :::465                  :::*                    LISTEN      1198/master
tcp6       0      0 :::8181                 :::*                    LISTEN      756/java
tcp6       0      0 :::5269                 :::*                    LISTEN      1226/lua5.2
tcp6       0      0 :::53                   :::*                    LISTEN      779/named
tcp6       0      0 :::22                   :::*                    LISTEN      795/sshd
4

Did you capture that while JVB was running and seeing the error?

5

its triggered every 10 sec

6

seems linked to healthCheck ?

JVB 2020-03-20 17:22:56.241 INFO: [38] org.jitsi.videobridge.health.Health.log() Performed a successful health check in 19ms. Sticky failure: false
JVB 2020-03-20 17:23:03.953 FINE: [230] org.jitsi.videobridge.xmpp.ComponentImpl.processIQ() (serving component 'JitsiVideobridge') Processing IQ (packetId JJHKo-824): <iq to="jitsi-videobridge.sub.mydomain
.tv" from="focus@auth.sub.mydomain.tv/focus18601256192" type="get" id="JJHKo-824"><healthcheck xmlns="http://jitsi.org/protocol/healthcheck"/></iq>
JVB 2020-03-20 17:23:03.953 FINE: [230] org.jitsi.videobridge.xmpp.ComponentImpl.processIQRequest() (serving component 'JitsiVideobridge') Processing IQ request (packetId JJHKo-824).
JVB 2020-03-20 17:23:03.955 FINE: [230] org.jitsi.videobridge.xmpp.ComponentImpl.processIQ() (serving component 'JitsiVideobridge') Responding to IQ (packetId JJHKo-824) with: <iq to="focus@auth.video.alpe
s.tv/focus18601256192" from="jitsi-videobridge.sub.mydomain.tv" id="JJHKo-824" type="result"/>
JVB 2020-03-20 17:23:04.292 FINE: [233] org.jitsi.videobridge.xmpp.ComponentImpl.processIQ() (serving component 'JitsiVideobridge') Processing IQ (packetId dd6Q4-384): <iq to="jitsi-videobridge.sub.mydomain
.tv" type="result" from="sub.mydomain.tv" id="dd6Q4-384"/>
JVB 2020-03-20 17:23:06.241 INFO: [38] org.jitsi.videobridge.Videobridge.log() CAT=stat create_conf,conf_id=20c87aa07a2e0a90 conf_name=null,logging=false,conf_count=2,ch_count=6,v_streams=4
JVB 2020-03-20 17:23:06.247 INFO: [38] org.ice4j.ice.harvest.HostCandidateHarvester.createDatagramSocket() Retrying a bind because of a failure to bind to address /MYIP.MYIP.MYIP.MYIP and port 10051 (Address al
ready in use (Bind failed))
JVB 2020-03-20 17:23:06.247 INFO: [38] org.ice4j.ice.harvest.HostCandidateHarvester.createDatagramSocket() Retrying a bind because of a failure to bind to address /MYIP.MYIP.MYIP.MYIP and port 10052 (Address al
ready in use (Bind failed))
JVB 2020-03-20 17:23:06.247 INFO: [38] org.ice4j.ice.harvest.HostCandidateHarvester.createDatagramSocket() Retrying a bind because of a failure to bind to address /MYIP.MYIP.MYIP.MYIP and port 10053 (Address al
ready in use (Bind failed))
JVB 2020-03-20 17:23:06.248 INFO: [38] org.ice4j.ice.harvest.HostCandidateHarvester.createDatagramSocket() Retrying a bind because of a failure to bind to address /MYIP.MYIP.MYIP.MYIP and port 10054 (Address al
ready in use (Bind failed))
JVB 2020-03-20 17:23:06.248 INFO: [38] org.ice4j.ice.harvest.HostCandidateHarvester.createDatagramSocket() Retrying a bind because of a failure to bind to address /MYIP.MYIP.MYIP.MYIP and port 10052 (Address al
ready in use (Bind failed))
JVB 2020-03-20 17:23:06.249 INFO: [38] org.ice4j.ice.harvest.HostCandidateHarvester.createDatagramSocket() Retrying a bind because of a failure to bind to address /MYIP.MYIP.MYIP.MYIP and port 10053 (Address al
ready in use (Bind failed))
JVB 2020-03-20 17:23:06.249 INFO: [38] org.ice4j.ice.harvest.HostCandidateHarvester.createDatagramSocket() Retrying a bind because of a failure to bind to address /MYIP.MYIP.MYIP.MYIP and port 10054 (Address al
ready in use (Bind failed))
JVB 2020-03-20 17:23:06.249 INFO: [38] org.ice4j.ice.harvest.HostCandidateHarvester.createDatagramSocket() Retrying a bind because of a failure to bind to address /MYIP.MYIP.MYIP.MYIP and port 10055 (Address al
ready in use (Bind failed))
7

What version of the bridge is this? We disabled attempting ICE connections for health checks a while back (in JVB 2, I thought they were already disabled in JVB 1)

8

how to check version ?
i used the quick install 7 day ago
i think its JVB1 knowing the JVB2.1 have just been annouced as stable , no ?

is it org.jitsi.jicofo.HEALTH_CHECK_INTERVAL=-1 to add ?

9

Ok, if you installed stable that’ll still be JVB 1. Maybe it’s still doing ICE connections in health checks after all. The reason we disabled them in JVB 2 is that they don’t work in single-port mode. You can see the comment here in JVB 2.

10

So yeah, you could disable the health checks, but this may or may not be problematic for you, depending on your deployment.

11

ok
org.jitsi.jicofo.HEALTH_CHECK_INTERVAL=-1
in jicofo/sip-communicator.propertie fail . No effect

im on Debian10 “buster”
so, im gonna wait a bit to update my JVB …
may if you have time to, you can add a “how to update JVB” below your annoucement ?

Whatever, in this trouble time, you are all doing a great job. Thank you very much

12

I can confirm this issue. I get the same error when trying to use a different port then 10000 as JVB_PORT using the (latest) official docker images.

jitsi-meet-jvb | JVB 2020-03-24 03:08:41.595 INFO: [1] org.jitsi.impl.configuration.ConfigurationServiceImpl.log() org.jitsi.videobridge.DISABLE_TCP_HARVESTER=true
[...]
jitsi-meet-jvb | JVB 2020-03-24 03:08:41.598 INFO: [1] org.jitsi.impl.configuration.ConfigurationServiceImpl.log() org.jitsi.videobridge.SINGLE_PORT_HARVESTER_PORT=20000                                                             
[...]
jitsi-meet-jvb | JVB 2020-03-24 03:08:42.020 INFO: [20] org.ice4j.ice.harvest.AbstractUdpListener.<init>() Initialized AbstractUdpListener with address 172.20.0.5:20000/udp. Receive buffer size 212992 (asked for 10485760)
jitsi-meet-jvb | JVB 2020-03-24 03:08:42.020 INFO: [20] org.ice4j.ice.harvest.SinglePortUdpHarvester.<init>() Initialized SinglePortUdpHarvester with address 172.20.0.5:20000/udp
[...]
jitsi-meet-jvb | JVB 2020-03-24 03:08:42.026 INFO: [20] org.ice4j.ice.harvest.HostCandidateHarvester.createDatagramSocket() Retrying a bind because of a failure to bind to address /172.20.0.5 and port 10001 (Address already in use
 (Bind failed))
jitsi-meet-jvb | JVB 2020-03-24 03:08:42.026 INFO: [20] org.ice4j.ice.harvest.HostCandidateHarvester.createDatagramSocket() Retrying a bind because of a failure to bind to address /172.20.0.5 and port 10002 (Address already in use
 (Bind failed))
jitsi-meet-jvb | JVB 2020-03-24 03:08:42.027 INFO: [20] org.ice4j.ice.harvest.HostCandidateHarvester.createDatagramSocket() Retrying a bind because of a failure to bind to address /172.20.0.5 and port 10003 (Address already in use
 (Bind failed))
jitsi-meet-jvb | JVB 2020-03-24 03:08:42.027 INFO: [20] org.ice4j.ice.harvest.HostCandidateHarvester.createDatagramSocket() Retrying a bind because of a failure to bind to address /172.20.0.5 and port 10004 (Address already in use
 (Bind failed))
jitsi-meet-jvb | JVB 2020-03-24 03:08:42.054 INFO: [20] org.ice4j.ice.harvest.HostCandidateHarvester.createDatagramSocket() Retrying a bind because of a failure to bind to address /172.20.0.5 and port 10002 (Address already in use
 (Bind failed))
jitsi-meet-jvb | JVB 2020-03-24 03:08:42.055 INFO: [20] org.ice4j.ice.harvest.HostCandidateHarvester.createDatagramSocket() Retrying a bind because of a failure to bind to address /172.20.0.5 and port 10003 (Address already in use
 (Bind failed))
jitsi-meet-jvb | JVB 2020-03-24 03:08:42.055 INFO: [20] org.ice4j.ice.harvest.HostCandidateHarvester.createDatagramSocket() Retrying a bind because of a failure to bind to address /172.20.0.5 and port 10004 (Address already in use
 (Bind failed))
jitsi-meet-jvb | JVB 2020-03-24 03:08:42.056 INFO: [20] org.ice4j.ice.harvest.HostCandidateHarvester.createDatagramSocket() Retrying a bind because of a failure to bind to address /172.20.0.5 and port 10005 (Address already in use
 (Bind failed))

With netstat I cannot detect any usage of the problematic ports

$ nsenter -t <pid.of.container> -n netstat -pltuna
Active Internet connections (servers and established)
Proto Recv-Q Send-Q Local Address           Foreign Address         State       PID/Program name
tcp        0      0 127.0.0.11:36253        0.0.0.0:*               LISTEN      7141/dockerd
tcp        0      0 172.20.0.4:58134        172.20.0.3:5222         ESTABLISHED 34791/java
udp        0      0 172.20.0.4:20000        0.0.0.0:*                           34791/java
udp        0      0 0.0.0.0:38172           0.0.0.0:*                           34791/java
udp        0      0 127.0.0.11:48350        0.0.0.0:*                           7141/dockerd

Used Docker Image / Package:

$ docker image inspect jitsi/jvb:latest -f '{{ .Created }}'
2019-12-04T14:17:42.038127168Z

$ docker exec -it jitsi-meet-jvb dpkg -l | grep jitsi
ii  jitsi-videobri 1124-1       amd64        WebRTC compatible Selective Forwa

Currently I’m out of ideas what’s the difference between running jvb @ 11000 or 20000 compared to 10000. It looks it tries to initiate the dynamic pool assignment when running in single_port mode.

Any ideas?

13

i tried many things and it seems that removing
#org.jitsi.videobridge.SINGLE_PORT_HARVESTER_PORT=10000 in sip-communicator.properties
solved it

at first install, i needed to specify a single port to avoid conflict with virtualmin
but then i changed the port of virtualmin

if it can help …