Videobridge Problems

Hey,

I’ve got problems running videobridge. It’s FreeBSD 12 system running a jail for Jitsi.

The problems seem to be be

  • No host harvesters available!
  • Failed to gather any host candidates!

leading to

  • Failed to bind single-port

Port 4443/tcp and 10000/udp are unused.

=> Does anyone please have a hint/idea?


sip-communicator.properties

org.ice4j.ipv6.DISABLED=true
org.ice4j.ice.harvest.NAT_HARVESTER_LOCAL_ADDRESS=[removed, internal]
org.ice4j.ice.harvest.NAT_HARVESTER_PUBLIC_ADDRESS=[removed, external_ip]
org.jitsi.videobridge.SINGLE_PORT_HARVESTER_PORT=10000
#org.jitsi.videobridge.DISABLE_TCP_HARVESTER=true
#org.ice4j.ice.harvest.DISABLE_AWS_HARVESTER=true
org.jitsi.videobridge.TCP_HARVESTER_PORT=4443
org.jitsi.videobridge.TCP_HARVESTER_MAPPED_PORT=4443

jitsi-videobridge.log

2020-06-24 21:11:25.323 INFORMATION: [1] NewConfig$1.invoke#88: Loaded NewConfig with origin: merge of system properties,system properties,reference.conf @ jar:file:/usr/local/share/java/classes/jitsi-videobridge.jar!/reference.conf: 1
2020-06-24 21:11:25.336 INFORMATION: [1] LegacyConfigFileLoader$Companion.load#40: Attempting to load legacy config file at path /usr/local/etc/jitsi, videobridge, sip-communicator.properties
2020-06-24 21:11:25.344 INFORMATION: [1] LegacyConfigFileLoader$Companion.load#40: Attempting to load legacy config file at path /usr/local/etc/jitsi, videobridge, sip-communicator.properties
2020-06-24 21:11:25.348 INFORMATION: [1] JitsiConfig$Companion.reload#40: Reloading.
2020-06-24 21:11:25.386 INFORMATION: [1] NewConfig$1.invoke#88: Loaded NewConfig with origin: merge of system properties,system properties,reference.conf @ jar:file:/usr/local/share/java/classes/jitsi-videobridge.jar!/reference.conf: 1
2020-06-24 21:11:25.387 INFORMATION: [1] LegacyConfigFileLoader$Companion.load#40: Attempting to load legacy config file at path /usr/local/etc/jitsi, videobridge, sip-communicator.properties
2020-06-24 21:11:25.388 INFORMATION: [1] LegacyConfigFileLoader$Companion.load#40: Attempting to load legacy config file at path /usr/local/etc/jitsi, videobridge, sip-communicator.properties
2020-06-24 21:11:25.481 INFORMATION: [21] ConfigurationActivator.start#45: Registered the LegacyConfigurationServiceShim in OSGi.
2020-06-24 21:11:25.487 INFORMATION: [21] AbstractVersionActivator.start#91: VersionService registered: JVB 2.1.SNAPSHOT
2020-06-24 21:11:25.505 INFORMATION: [21] AbstractJettyBundleActivator.start#613: Not starting the Jetty service for org.jitsi.videobridge.rest.RESTBundleActivator(port=8080)
2020-06-24 21:11:25.545 INFORMATION: [21] AbstractJettyBundleActivator.start#613: Not starting the Jetty service for org.jitsi.videobridge.websocket.WebSocketBundleActivator(port=-1)
2020-06-24 21:11:25.610 INFORMATION: [21] UlimitCheck.printUlimits#115: Running with open files limit 1875798 (hard 1875798), thread limit 63464 (hard 63464).
2020-06-24 21:11:25.617 INFORMATION: [21] VideobridgeExpireThread.start#92: Starting with 60 second interval.
2020-06-24 21:11:25.620 WARNUNG: [21] Videobridge.start#909: No authorized source regexp configured. Will accept requests from any source.
2020-06-24 21:11:25.900 INFORMATION: [21] JitsiConfig$Companion.reload#40: Reloading.
2020-06-24 21:11:25.917 INFORMATION: [21] NewConfig$1.invoke#88: Loaded NewConfig with origin: merge of system properties,system properties,reference.conf @ jar:file:/usr/local/share/java/classes/jitsi-videobridge.jar!/reference.conf: 1
2020-06-24 21:11:25.918 INFORMATION: [21] LegacyConfigFileLoader$Companion.load#40: Attempting to load legacy config file at path /usr/local/etc/jitsi, videobridge, sip-communicator.properties
2020-06-24 21:11:25.919 INFORMATION: [21] LegacyConfigFileLoader$Companion.load#40: Attempting to load legacy config file at path /usr/local/etc/jitsi, videobridge, sip-communicator.properties
2020-06-24 21:11:25.948 INFORMATION: [21] AbstractHealthCheckService.start#96: Started with interval=10000, timeout=PT30S, maxDuration=PT3S, stickyFailures=false.
2020-06-24 21:11:25.984 INFORMATION: [21] OctoRelayService.start#62: Octo relay is disabled.
2020-06-24 21:11:25.993 INFORMATION: [1] java.util.prefs.FileSystemPreferences$1.run: Created user preferences directory.
2020-06-24 21:11:26.130 INFORMATION: [30] ComponentBase.loadConfig#202: Component org.jitsi.videobridge. config:
2020-06-24 21:11:26.131 INFORMATION: [30] ComponentBase.loadConfig#203:   ping interval: 10000 ms
2020-06-24 21:11:26.131 INFORMATION: [30] ComponentBase.loadConfig#204:   ping timeout: 5000 ms
2020-06-24 21:11:26.132 INFORMATION: [30] ComponentBase.loadConfig#205:   ping threshold: 3
2020-06-24 21:11:26.494 INFORMATION: [25] org.ice4j.ice.harvest.MappingCandidateHarvesters.initialize: Using org.ice4j.ice.harvest.MappingCandidateHarvester, face=/[removed, internal], mask=/[removed, external]
2020-06-24 21:11:26.494 INFORMATION: [25] org.ice4j.ice.harvest.MappingCandidateHarvesters.initialize: Initialized mapping harvesters (delay=559ms).  stunDiscoveryFailed=false
2020-06-24 21:11:56.104 INFORMATION: [1] NewConfig$1.invoke#88: Loaded NewConfig with origin: merge of system properties,system properties,reference.conf @ jar:file:/usr/local/share/java/classes/jitsi-videobridge.jar!/reference.conf: 1
2020-06-24 21:11:56.112 INFORMATION: [1] LegacyConfigFileLoader$Companion.load#40: Attempting to load legacy config file at path /usr/local/etc/jitsi, videobridge, sip-communicator.properties
2020-06-24 21:11:56.117 INFORMATION: [1] LegacyConfigFileLoader$Companion.load#40: Attempting to load legacy config file at path /usr/local/etc/jitsi, videobridge, sip-communicator.properties
2020-06-24 21:11:56.120 INFORMATION: [1] JitsiConfig$Companion.reload#40: Reloading.
2020-06-24 21:11:56.146 INFORMATION: [1] NewConfig$1.invoke#88: Loaded NewConfig with origin: merge of system properties,system properties,reference.conf @ jar:file:/usr/local/share/java/classes/jitsi-videobridge.jar!/reference.conf: 1
2020-06-24 21:11:56.146 INFORMATION: [1] LegacyConfigFileLoader$Companion.load#40: Attempting to load legacy config file at path /usr/local/etc/jitsi, videobridge, sip-communicator.properties
2020-06-24 21:11:56.147 INFORMATION: [1] LegacyConfigFileLoader$Companion.load#40: Attempting to load legacy config file at path /usr/local/etc/jitsi, videobridge, sip-communicator.properties
2020-06-24 21:11:56.205 INFORMATION: [21] ConfigurationActivator.start#45: Registered the LegacyConfigurationServiceShim in OSGi.
2020-06-24 21:11:56.209 INFORMATION: [21] AbstractVersionActivator.start#91: VersionService registered: JVB 2.1.SNAPSHOT
2020-06-24 21:11:56.220 INFORMATION: [21] AbstractJettyBundleActivator.start#613: Not starting the Jetty service for org.jitsi.videobridge.rest.RESTBundleActivator(port=8080)
2020-06-24 21:11:56.246 INFORMATION: [21] AbstractJettyBundleActivator.start#613: Not starting the Jetty service for org.jitsi.videobridge.websocket.WebSocketBundleActivator(port=-1)
2020-06-24 21:11:56.287 INFORMATION: [21] UlimitCheck.printUlimits#115: Running with open files limit 1875798 (hard 1875798), thread limit 63464 (hard 63464).
2020-06-24 21:11:56.291 INFORMATION: [21] VideobridgeExpireThread.start#92: Starting with 60 second interval.
2020-06-24 21:11:56.293 WARNUNG: [21] Videobridge.start#909: No authorized source regexp configured. Will accept requests from any source.
2020-06-24 21:11:56.469 INFORMATION: [21] JitsiConfig$Companion.reload#40: Reloading.
2020-06-24 21:11:56.479 INFORMATION: [21] NewConfig$1.invoke#88: Loaded NewConfig with origin: merge of system properties,system properties,reference.conf @ jar:file:/usr/local/share/java/classes/jitsi-videobridge.jar!/reference.conf: 1
2020-06-24 21:11:56.479 INFORMATION: [21] LegacyConfigFileLoader$Companion.load#40: Attempting to load legacy config file at path /usr/local/etc/jitsi, videobridge, sip-communicator.properties
2020-06-24 21:11:56.480 INFORMATION: [21] LegacyConfigFileLoader$Companion.load#40: Attempting to load legacy config file at path /usr/local/etc/jitsi, videobridge, sip-communicator.properties
2020-06-24 21:11:56.497 INFORMATION: [21] AbstractHealthCheckService.start#96: Started with interval=10000, timeout=PT30S, maxDuration=PT3S, stickyFailures=false.
2020-06-24 21:11:56.518 INFORMATION: [21] OctoRelayService.start#62: Octo relay is disabled.
2020-06-24 21:11:56.598 INFORMATION: [30] ComponentBase.loadConfig#202: Component org.jitsi.videobridge. config:
2020-06-24 21:11:56.599 INFORMATION: [30] ComponentBase.loadConfig#203:   ping interval: 10000 ms
2020-06-24 21:11:56.599 INFORMATION: [30] ComponentBase.loadConfig#204:   ping timeout: 5000 ms
2020-06-24 21:11:56.599 INFORMATION: [30] ComponentBase.loadConfig#205:   ping threshold: 3
2020-06-24 21:11:57.007 INFORMATION: [25] org.ice4j.ice.harvest.MappingCandidateHarvesters.initialize: Using org.ice4j.ice.harvest.MappingCandidateHarvester, face=/[removed, internal], mask=/[removed, external]
2020-06-24 21:11:57.007 INFORMATION: [25] org.ice4j.ice.harvest.MappingCandidateHarvesters.initialize: Initialized mapping harvesters (delay=518ms).  stunDiscoveryFailed=false
2020-06-24 21:12:06.548 INFORMATION: [26] Videobridge.createConference#319: create_conf, id=[replaced, 3...] gid=null logging=false
2020-06-24 21:12:06.591 INFORMATION: [26] TaskPools.<clinit>#81: TaskPools detected 4 processors, creating the CPU pool with that many threads
2020-06-24 21:12:06.967 INFORMATION: [26] Harvesters.initializeStaticConfiguration#90: No single-port harvesters created.
2020-06-24 21:12:07.000 WARNUNG: [26] [confId=[replaced, 3...] epId=[replaced, f...] local_ufrag=[replaced, a...] ufrag=[replaced, a...]] Agent.gatherCandidates#674: No host harvesters available!
2020-06-24 21:12:07.001 WARNUNG: [26] [confId=[replaced, 3...] epId=[replaced, f...] local_ufrag=[replaced, a...] ufrag=[replaced, a...]] Agent.gatherCandidates#683: Failed to gather any host candidates!
SCTP JNI load: FreeBSD OS detected
SCTP lib loaded
=====>: org_jitsi_modified_sctp4j_SctpJni.c calling init
2020-06-24 21:12:08.267 WARNUNG: [26] [confId=[replaced, 3...] epId=a3679191 local_ufrag=[replaced, doj...] ufrag=[replaced, doj...]] Agent.gatherCandidates#674: No host harvesters available!
2020-06-24 21:12:08.267 WARNUNG: [26] [confId=[replaced, 3...] epId=a3679191 local_ufrag=[replaced, doj...] ufrag=[replaced, doj...]] Agent.gatherCandidates#683: Failed to gather any host candidates!
2020-06-24 21:12:08.283 INFORMATION: [26] AbstractHealthCheckService.run#171: Performed a successful health check in PT1.784S. Sticky failure: false
2020-06-24 21:12:16.502 SCHWERWIEGEND: [26] AbstractHealthCheckService.run#174: Health check failed in PT0.001S:
java.lang.Exception: Failed to bind single-port
	at org.jitsi.videobridge.health.Health.performCheck(Health.java:200)
	at org.jitsi.health.AbstractHealthCheckService.run(AbstractHealthCheckService.kt:144)
	at org.jitsi.utils.concurrent.RecurringRunnableExecutor.run(RecurringRunnableExecutor.java:216)
	at org.jitsi.utils.concurrent.RecurringRunnableExecutor.runInThread(RecurringRunnableExecutor.java:292)
	at org.jitsi.utils.concurrent.RecurringRunnableExecutor.access$000(RecurringRunnableExecutor.java:36)
	at org.jitsi.utils.concurrent.RecurringRunnableExecutor$1.run(RecurringRunnableExecutor.java:328)
2020-06-24 21:12:26.507 SCHWERWIEGEND: [26] AbstractHealthCheckService.run#174: Health check failed in PT0S:
java.lang.Exception: Failed to bind single-port
	at org.jitsi.videobridge.health.Health.performCheck(Health.java:200)
	at org.jitsi.health.AbstractHealthCheckService.run(AbstractHealthCheckService.kt:144)
	at org.jitsi.utils.concurrent.RecurringRunnableExecutor.run(RecurringRunnableExecutor.java:216)
	at org.jitsi.utils.concurrent.RecurringRunnableExecutor.runInThread(RecurringRunnableExecutor.java:292)
	at org.jitsi.utils.concurrent.RecurringRunnableExecutor.access$000(RecurringRunnableExecutor.java:36)
	at org.jitsi.utils.concurrent.RecurringRunnableExecutor$1.run(RecurringRunnableExecutor.java:328)
2020-06-24 21:12:36.513 SCHWERWIEGEND: [26] AbstractHealthCheckService.run#174: Health check failed in PT0S:
java.lang.Exception: Failed to bind single-port
	at org.jitsi.videobridge.health.Health.performCheck(Health.java:200)
	at org.jitsi.health.AbstractHealthCheckService.run(AbstractHealthCheckService.kt:144)
	at org.jitsi.utils.concurrent.RecurringRunnableExecutor.run(RecurringRunnableExecutor.java:216)
	at org.jitsi.utils.concurrent.RecurringRunnableExecutor.runInThread(RecurringRunnableExecutor.java:292)
	at org.jitsi.utils.concurrent.RecurringRunnableExecutor.access$000(RecurringRunnableExecutor.java:36)
	at org.jitsi.utils.concurrent.RecurringRunnableExecutor$1.run(RecurringRunnableExecutor.java:328)

I have exact the same problem and can’t find a solution. Did you find the reason why it’s not working? I’m running FreeBSD 12.1 in a Jail. Video with two participant works but as soon a third party joins video and audio goes down. Seems like it’s due to this problem

Helpful were:

But there’s nothing new. Still doesn’t work.

Seems to be a problem with https:// github. com / jitsi/ice4j/blob/686164ffc4633c86f2f23c9e542119ac3da42cae/src/main/java/org/ice4j/ice/harvest/SinglePortUdpHarvester.java#L78. Testing the ports with netcat inside the jails worked (tcp and udp). Maybe it is looking at the wrong interface or the legacy preferences format (sip-communicator.properties) is not accepted. Trying the new application.conf didn’t work either.

To me it seems like the sip-communicator.properties is interpreted because I get also the following message in the log

2020-07-04 21:25:24.502 INFO: [17] org.ice4j.ice.harvest.MappingCandidateHarvesters.initialize: Using org.ice4j.ice.harvest.MappingCandidateHarvester, face=/172.16.2.26, mask=/<<public IP address>>

Which I set by the lines:

org.ice4j.ice.harvest.NAT_HARVESTER_LOCAL_ADDRESS=172.16.2.26
org.ice4j.ice.harvest.NAT_HARVESTER_PUBLIC_ADDRESS=<<public IP address>>

I did not manage to turn the logs more aggressive which should be done in /usr/local/share/java/jitsi-videobridge-2.1.183/lib/logging.properties. Did you try to set the logs to DEBUG instead of INFO?

Perhaps you could try the following for more verbose logging.

handlers= java.util.logging.ConsoleHandler
#handlers= java.util.logging.ConsoleHandler, com.agafua.syslog.SyslogHandler

java.util.logging.ConsoleHandler.level = FINEST
java.util.logging.ConsoleHandler.formatter = org.jitsi.utils.logging2.JitsiLogFormatter

net.java.sip.communicator.util.ScLogFormatter.programname=JVB

.level=FINEST

org.jitsi.videobridge.xmpp.ComponentImpl.level=FINEST

org.jitsi.videobridge.ice.Harvesters.level=FINEST
org.ice4j.ice.harvest.TcpHarvester.level=FINEST
org.ice4j.ice.harvest.UdpHarvester.level=FINEST
org.ice4j.ice.harvest.SinglePortUdpHarvester.level=FINEST
org.ice4j.level=FINEST
test.level=FINEST
org.ice4j.harvest.level=FINEST

# FINEST of the INFO level logs from MediaStreamImpl are unnecessary in the context of jitsi-videobridge.
org.jitsi.impl.neomedia.MediaStreamImpl.level=FINEST

# Syslog(uncomment handler to use)
#com.agafua.syslog.SyslogHandler.transport = udp
#com.agafua.syslog.SyslogHandler.facility = local0
#com.agafua.syslog.SyslogHandler.port = 514
#com.agafua.syslog.SyslogHandler.hostname = localhost
#com.agafua.syslog.SyslogHandler.formatter = org.jitsi.utils.logging2.JitsiLogFormatter
#com.agafua.syslog.SyslogHandler.escapeNewlines = false

# to disable double timestamps in syslog uncomment next line
#net.java.sip.communicator.util.ScLogFormatter.disableTimestamp=true

# time series logging
java.util.logging.SimpleFormatter.format= %5$s%n
java.util.logging.FileHandler.level = FINEST
java.util.logging.FileHandler.formatter = java.util.logging.SimpleFormatter
java.util.logging.FileHandler.pattern = /tmp/jvb-series.log
java.util.logging.FileHandler.limit = 200000000
java.util.logging.FileHandler.count = 1
java.util.logging.FileHandler.append = false

timeseries.level=FINEST
timeseries.org.jitsi.videobridge.cc.vp8.level=FINEST
timeseries.useParentHandlers = false
timeseries.handlers = java.util.logging.FileHandler

This is just to report that I am getting the exact same issue on FreeBSD 11.3. Spent so much time trying to troubleshoot it but I think the problem seems to be with Jitsi itself. Making the logs aggressive requires setting them to “FINE” (and not DEBUG). Setting it that way shows that the NAT_HARVESTER_PUBLIC_ADDRESS properties are being correctly interpreted.

What about this one? Seems something is already listening on port 10000 udp.

This is what I assumed too but unfortunately there is nothing running on that port. The others posters on this thread seem to report the same

USER     COMMAND    PID   FD PROTO  LOCAL ADDRESS         FOREIGN ADDRESS      
root     java       33177 8  tcp4   192.168.185.18:8080   *:*
root     java       33177 43 udp4   192.168.185.18:5000   *:*
root     java       31451 7  udp4   192.168.185.18:12001  *:*
root     java       31451 21 tcp4   192.168.185.18:8888   *:*
prosody  lua52      31137 3  tcp4   192.168.185.18:5222   *:*
prosody  lua52      31137 5  tcp4   192.168.185.18:5347   *:*
prosody  lua52      31137 9  tcp4   192.168.185.18:5280   *:*
prosody  lua52      31137 10 tcp4   192.168.185.18:5269   *:*
root     sendmail   90408 4  tcp4   192.168.185.18:25     *:*
root     httpd      90398 3  tcp4   192.168.185.18:80     *:*
root     httpd      90398 4  tcp4   192.168.185.18:15300  *:*
root     syslogd    90334 5  udp4   192.168.185.18:514    *:*

Looking at the source code, the class throwing the exception “No host harvesters available!” seems to be this one:

Now I am trying to figure out why there is no host registered. On freebsd, the jitsi-videobridge service is started with the options

${videobridgecommand} -Xmx${VIDEOBRIDGE_MAX_MEMORY} \
                -XX:+UseConcMarkSweepGC \
                -XX:+HeapDumpOnOutOfMemoryError \
                -XX:HeapDumpPath=/tmp \
                -Djava.util.logging.config.file=${jitsi_videobridge_logging_config} \
                -Dnet.java.sip.communicator.SC_HOME_DIR_LOCATION=/usr/local/etc/jitsi \
                -Dnet.java.sip.communicator.SC_HOME_DIR_NAME=videobridge \
                -Dnet.java.sip.communicator.SC_LOG_DIR_LOCATION=/var/log/ \
                -cp ${jitsi_videobridge_jar} \
                org.jitsi.videobridge.Main \
                --host=${JVB_XMPP_HOST} \
                --domain=${JVB_XMPP_DOMAIN} \
                --port=${JVB_XMPP_PORT} \
                --secret=${JVB_XMPP_SECRET} ${jitsi_videobridge_flags}

I stumbled over the same problem. After playing around a while i figured out that as soon as i gave my host a second ip address (em0_alias) and make it available in the jail it starts and bind port 10000 specific to this address. No matter what ip i write to NAT_HARVESTER_PUBLIC_ADDRESS, jvb refuse to bind on a loopbackaddress.

So JVB will not bind to an lo interface in FreeBSD? you have to have an ip on a physical interface? has anyone tried VNET?