Upgrade to JVB 2 on Ubuntu 18.04 -- ice4j "Pair Failed"

I upgraded a working Jitsi Meet install running on Ubuntu 18.04 the other day, and afterward the ice4j ConnectivityCheckClient is giving “Pair failed” messages when attempting to setup streams for clients behind a NAT. As a result those clients are not receiving any media streams.

The system running the install has a public IP address and was initially setup using the previous version of the quick install guide (prior to the switch to JVB 2).

Here’s a snippet from my jvb.log of a conference being setup between NATed clients:

2020-03-29 20:09:02.555 INFO: [65] Videobridge.createConference#326: create_conf, id=12965e6729766a64 gid=ff5f5f logging=true
2020-03-29 20:09:02.559 INFO: [65] [confId=12965e6729766a64 epId=a562034d gid=ff5f5f conf_name=testconf ufrag=4q8v71e4kfo6eu] Agent.gatherCandidates#660: Gathering candidates for component stream-a562034d.RTP. Local ufrag 4q8v71e4kfo6eu
2020-03-29 20:09:02.562 INFO: [31] [confId=12965e6729766a64 gid=ff5f5f conf_name=testconf] Conference.dominantSpeakerChanged#446: ds_change ds_id=a562034d
2020-03-29 20:09:02.566 INFO: [65] [confId=12965e6729766a64 epId=a562034d local_ufrag=4q8v71e4kfo6eu gid=ff5f5f conf_name=testconf] DtlsTransport.lambda$startConnectivityEstablishment$1#181: 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-03-29 20:09:03.076 INFO: [65] [confId=12965e6729766a64 epId=a562034d local_ufrag=4q8v71e4kfo6eu gid=ff5f5f stats_id=Keeley-7WI conf_name=testconf] DtlsTransport.startConnectivityEstablishment#195: The remote side is acting as DTLS server, we'll act as client
2020-03-29 20:09:03.077 INFO: [65] [confId=12965e6729766a64 gid=ff5f5f stats_id=Keeley-7WI componentId=1 conf_name=testconf ufrag=4q8v71e4kfo6eu name=stream-a562034d epId=a562034d local_ufrag=4q8v71e4kfo6eu] Component.addRemoteCandidate#330: Add remote candidate for stream-a562034d.RTP: 192.168.0.72:49353/udp/host
2020-03-29 20:09:03.077 INFO: [65] [confId=12965e6729766a64 epId=a562034d local_ufrag=4q8v71e4kfo6eu gid=ff5f5f stats_id=Keeley-7WI conf_name=testconf] IceTransport.startConnectivityEstablishment#404: Starting the agent with remote candidates.
2020-03-29 20:09:03.077 INFO: [65] [confId=12965e6729766a64 gid=ff5f5f stats_id=Keeley-7WI conf_name=testconf ufrag=4q8v71e4kfo6eu epId=a562034d local_ufrag=4q8v71e4kfo6eu] Agent.startConnectivityEstablishment#751: Start ICE connectivity establishment. Local ufrag 4q8v71e4kfo6eu
2020-03-29 20:09:03.077 INFO: [65] [confId=12965e6729766a64 gid=ff5f5f stats_id=Keeley-7WI conf_name=testconf ufrag=4q8v71e4kfo6eu epId=a562034d local_ufrag=4q8v71e4kfo6eu] Agent.initCheckLists#995: Init checklist for stream stream-a562034d
2020-03-29 20:09:03.078 INFO: [65] [confId=12965e6729766a64 gid=ff5f5f stats_id=Keeley-7WI conf_name=testconf ufrag=4q8v71e4kfo6eu epId=a562034d local_ufrag=4q8v71e4kfo6eu] Agent.setState#962: ICE state changed from Waiting to Running. Local ufrag 4q8v71e4kfo6eu
2020-03-29 20:09:03.078 INFO: [65] [confId=12965e6729766a64 epId=a562034d local_ufrag=4q8v71e4kfo6eu gid=ff5f5f stats_id=Keeley-7WI conf_name=testconf] IceTransport.iceStateChange#605: ICE state changed old=Waiting new=Running
2020-03-29 20:09:03.078 INFO: [65] [confId=12965e6729766a64 gid=ff5f5f stats_id=Keeley-7WI conf_name=testconf ufrag=4q8v71e4kfo6eu epId=a562034d local_ufrag=4q8v71e4kfo6eu] ConnectivityCheckClient.startChecks#142: Start connectivity checks. Local ufrag 4q8v71e4kfo6eu
2020-03-29 20:09:03.086 INFO: [65] [confId=12965e6729766a64 gid=ff5f5f stats_id=Keeley-7WI componentId=1 conf_name=testconf ufrag=4q8v71e4kfo6eu name=stream-a562034d epId=a562034d local_ufrag=4q8v71e4kfo6eu] Component.addUpdateRemoteCandidates#347: Update remote candidate for stream-a562034d.RTP: 192.168.0.72:49353/udp
2020-03-29 20:09:03.086 INFO: [65] [confId=12965e6729766a64 gid=ff5f5f stats_id=Keeley-7WI componentId=1 conf_name=testconf ufrag=4q8v71e4kfo6eu name=stream-a562034d epId=a562034d local_ufrag=4q8v71e4kfo6eu] Component.addUpdateRemoteCandidates#369: Not adding duplicate remote candidate: 192.168.0.72:49353/udp
2020-03-29 20:09:03.087 INFO: [65] [confId=12965e6729766a64 gid=ff5f5f stats_id=Keeley-7WI componentId=1 conf_name=testconf ufrag=4q8v71e4kfo6eu name=stream-a562034d epId=a562034d local_ufrag=4q8v71e4kfo6eu] Component.addUpdateRemoteCandidates#347: Update remote candidate for stream-a562034d.RTP: 192.168.0.72:49353/udp
2020-03-29 20:09:03.088 INFO: [116] [confId=12965e6729766a64 gid=ff5f5f stats_id=Keeley-7WI componentId=1 conf_name=testconf ufrag=4q8v71e4kfo6eu name=stream-a562034d epId=a562034d local_ufrag=4q8v71e4kfo6eu] Component.addUpdateRemoteCandidates#347: Update remote candidate for stream-a562034d.RTP: 192.168.0.72:49353/udp
2020-03-29 20:09:03.088 INFO: [65] [confId=12965e6729766a64 gid=ff5f5f stats_id=Keeley-7WI componentId=1 conf_name=testconf ufrag=4q8v71e4kfo6eu name=stream-a562034d epId=a562034d local_ufrag=4q8v71e4kfo6eu] Component.addUpdateRemoteCandidates#369: Not adding duplicate remote candidate: 192.168.0.72:49353/udp
2020-03-29 20:09:03.089 INFO: [116] [confId=12965e6729766a64 gid=ff5f5f stats_id=Keeley-7WI componentId=1 conf_name=testconf ufrag=4q8v71e4kfo6eu name=stream-a562034d epId=a562034d local_ufrag=4q8v71e4kfo6eu] Component.addUpdateRemoteCandidates#369: Not adding duplicate remote candidate: 192.168.0.72:49353/udp
2020-03-29 20:09:03.090 INFO: [116] [confId=12965e6729766a64 gid=ff5f5f stats_id=Keeley-7WI componentId=1 conf_name=testconf ufrag=4q8v71e4kfo6eu name=stream-a562034d epId=a562034d local_ufrag=4q8v71e4kfo6eu] Component.addUpdateRemoteCandidates#347: Update remote candidate for stream-a562034d.RTP: 192.168.0.72:49353/udp
2020-03-29 20:09:03.090 INFO: [116] [confId=12965e6729766a64 gid=ff5f5f stats_id=Keeley-7WI componentId=1 conf_name=testconf ufrag=4q8v71e4kfo6eu name=stream-a562034d epId=a562034d local_ufrag=4q8v71e4kfo6eu] Component.addUpdateRemoteCandidates#369: Not adding duplicate remote candidate: 192.168.0.72:49353/udp
2020-03-29 20:09:03.102 INFO: [117] [confId=12965e6729766a64 gid=ff5f5f stats_id=Keeley-7WI conf_name=testconf ufrag=4q8v71e4kfo6eu epId=a562034d local_ufrag=4q8v71e4kfo6eu] ConnectivityCheckClient$PaceMaker.run#922: Pair failed: 139.78.2.37:10000/udp/host -> 192.168.0.72:49353/udp/host (stream-a562034d.RTP)
2020-03-29 20:09:04.448 INFO: [116] [confId=12965e6729766a64 epId=c100bc70 gid=ff5f5f conf_name=testconf ufrag=diba71e4kfo89v] Agent.gatherCandidates#660: Gathering candidates for component stream-c100bc70.RTP. Local ufrag diba71e4kfo89v
2020-03-29 20:09:04.479 INFO: [116] [confId=12965e6729766a64 epId=c100bc70 local_ufrag=diba71e4kfo89v gid=ff5f5f conf_name=testconf] DtlsTransport.lambda$startConnectivityEstablishment$1#181: 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-03-29 20:09:05.542 INFO: [116] [confId=12965e6729766a64 epId=c100bc70 local_ufrag=diba71e4kfo89v gid=ff5f5f stats_id=Edgardo-Uzb conf_name=testconf] DtlsTransport.startConnectivityEstablishment#190: The remote side is acting as DTLS client, we'll act as server
2020-03-29 20:09:05.543 INFO: [116] [confId=12965e6729766a64 epId=c100bc70 local_ufrag=diba71e4kfo89v gid=ff5f5f stats_id=Edgardo-Uzb conf_name=testconf] IceTransport.startConnectivityEstablishment#413: Starting the Agent without remote candidates. 
2020-03-29 20:09:05.543 INFO: [116] [confId=12965e6729766a64 gid=ff5f5f stats_id=Edgardo-Uzb conf_name=testconf ufrag=diba71e4kfo89v epId=c100bc70 local_ufrag=diba71e4kfo89v] Agent.startConnectivityEstablishment#751: Start ICE connectivity establishment. Local ufrag diba71e4kfo89v
2020-03-29 20:09:05.543 INFO: [116] [confId=12965e6729766a64 gid=ff5f5f stats_id=Edgardo-Uzb conf_name=testconf ufrag=diba71e4kfo89v epId=c100bc70 local_ufrag=diba71e4kfo89v] Agent.initCheckLists#995: Init checklist for stream stream-c100bc70
2020-03-29 20:09:05.544 INFO: [116] [confId=12965e6729766a64 gid=ff5f5f stats_id=Edgardo-Uzb conf_name=testconf ufrag=diba71e4kfo89v epId=c100bc70 local_ufrag=diba71e4kfo89v] Agent.setState#962: ICE state changed from Waiting to Running. Local ufrag diba71e4kfo89v
2020-03-29 20:09:05.544 INFO: [116] [confId=12965e6729766a64 epId=c100bc70 local_ufrag=diba71e4kfo89v gid=ff5f5f stats_id=Edgardo-Uzb conf_name=testconf] IceTransport.iceStateChange#605: ICE state changed old=Waiting new=Running
2020-03-29 20:09:05.544 INFO: [116] [confId=12965e6729766a64 gid=ff5f5f stats_id=Edgardo-Uzb conf_name=testconf ufrag=diba71e4kfo89v epId=c100bc70 local_ufrag=diba71e4kfo89v] ConnectivityCheckClient.startChecks#142: Start connectivity checks. Local ufrag diba71e4kfo89v
2020-03-29 20:09:05.545 INFO: [65] [confId=12965e6729766a64 gid=ff5f5f stats_id=Edgardo-Uzb componentId=1 conf_name=testconf ufrag=diba71e4kfo89v name=stream-c100bc70 epId=c100bc70 local_ufrag=diba71e4kfo89v] Component.addUpdateRemoteCandidates#347: Update remote candidate for stream-c100bc70.RTP: 192.168.200.254:56175/udp
2020-03-29 20:09:05.548 INFO: [65] [confId=12965e6729766a64 gid=ff5f5f stats_id=Edgardo-Uzb componentId=1 conf_name=testconf ufrag=diba71e4kfo89v name=stream-c100bc70 epId=c100bc70 local_ufrag=diba71e4kfo89v] Component.addUpdateRemoteCandidates#347: Update remote candidate for stream-c100bc70.RTP: 192.168.43.167:56178/udp
2020-03-29 20:09:05.549 INFO: [65] [confId=12965e6729766a64 gid=ff5f5f stats_id=Edgardo-Uzb componentId=1 conf_name=testconf ufrag=diba71e4kfo89v name=stream-c100bc70 epId=c100bc70 local_ufrag=diba71e4kfo89v] Component.updateRemoteCandidates#440: new Pair added: 139.78.2.37:10000/udp/host -> 192.168.200.254:56175/udp/host (stream-c100bc70.RTP). Local ufrag diba71e4kfo89v
2020-03-29 20:09:05.549 INFO: [65] [confId=12965e6729766a64 gid=ff5f5f stats_id=Edgardo-Uzb componentId=1 conf_name=testconf ufrag=diba71e4kfo89v name=stream-c100bc70 epId=c100bc70 local_ufrag=diba71e4kfo89v] Component.updateRemoteCandidates#440: new Pair added: 139.78.2.37:10000/udp/host -> 192.168.43.167:56178/udp/host (stream-c100bc70.RTP). Local ufrag diba71e4kfo89v
2020-03-29 20:09:05.566 INFO: [117] [confId=12965e6729766a64 gid=ff5f5f stats_id=Edgardo-Uzb conf_name=testconf ufrag=diba71e4kfo89v epId=c100bc70 local_ufrag=diba71e4kfo89v] ConnectivityCheckClient$PaceMaker.run#922: Pair failed: 139.78.2.37:10000/udp/host -> 192.168.200.254:56175/udp/host (stream-c100bc70.RTP)
2020-03-29 20:09:05.588 INFO: [117] [confId=12965e6729766a64 gid=ff5f5f stats_id=Edgardo-Uzb conf_name=testconf ufrag=diba71e4kfo89v epId=c100bc70 local_ufrag=diba71e4kfo89v] ConnectivityCheckClient$PaceMaker.run#922: Pair failed: 139.78.2.37:10000/udp/host -> 192.168.43.167:56178/udp/host (stream-c100bc70.RTP)
2020-03-29 20:09:06.044 INFO: [18] Videobridge.createConference#326: create_conf, id=cb6bc42a052474b9 gid=null logging=false
2020-03-29 20:09:06.057 INFO: [18] Health.doRun#294: Performed a successful health check in 13ms. Sticky failure: false
2020-03-29 20:09:16.058 INFO: [18] Videobridge.createConference#326: create_conf, id=a63775a179bd2ff gid=null logging=false
2020-03-29 20:09:16.071 INFO: [18] Health.doRun#294: Performed a successful health check in 13ms. Sticky failure: false
2020-03-29 20:09:26.072 INFO: [18] Videobridge.createConference#326: create_conf, id=a0c88380718a0ad9 gid=null logging=false
2020-03-29 20:09:26.086 INFO: [18] Health.doRun#294: Performed a successful health check in 15ms. Sticky failure: false
2020-03-29 20:09:28.486 INFO: [65] [confId=12965e6729766a64 epId=a562034d gid=ff5f5f stats_id=Keeley-7WI conf_name=testconf] AbstractEndpoint.expire#301: Expiring.
2020-03-29 20:09:28.487 INFO: [31] [confId=12965e6729766a64 gid=ff5f5f conf_name=testconf] Conference.dominantSpeakerChanged#446: ds_change ds_id=c100bc70
2020-03-29 20:09:28.489 INFO: [65] [confId=12965e6729766a64 gid=ff5f5f stats_id=Keeley-7WI conf_name=testconf ufrag=4q8v71e4kfo6eu epId=a562034d local_ufrag=4q8v71e4kfo6eu] Agent.setState#962: ICE state changed from Running to Terminated. Local ufrag 4q8v71e4kfo6eu
2020-03-29 20:09:28.489 INFO: [65] [confId=12965e6729766a64 gid=ff5f5f stats_id=Keeley-7WI componentId=1 conf_name=testconf ufrag=4q8v71e4kfo6eu name=stream-a562034d epId=a562034d local_ufrag=4q8v71e4kfo6eu] MergingDatagramSocket.close#142: Closing.
2020-03-29 20:09:28.490 INFO: [65] [confId=12965e6729766a64 epId=a562034d gid=ff5f5f stats_id=Keeley-7WI conf_name=testconf] Endpoint.expire#649: Expired.
2020-03-29 20:09:32.329 INFO: [65] [confId=12965e6729766a64 epId=c100bc70 gid=ff5f5f stats_id=Edgardo-Uzb conf_name=testconf] AbstractEndpoint.expire#301: Expiring.
2020-03-29 20:09:32.330 INFO: [31] [confId=12965e6729766a64 gid=ff5f5f conf_name=testconf] Conference.dominantSpeakerChanged#446: ds_change ds_id=null
2020-03-29 20:09:32.333 INFO: [65] [confId=12965e6729766a64 gid=ff5f5f stats_id=Edgardo-Uzb conf_name=testconf ufrag=diba71e4kfo89v epId=c100bc70 local_ufrag=diba71e4kfo89v] Agent.setState#962: ICE state changed from Running to Terminated. Local ufrag diba71e4kfo89v
2020-03-29 20:09:32.333 INFO: [65] [confId=12965e6729766a64 gid=ff5f5f stats_id=Edgardo-Uzb componentId=1 conf_name=testconf ufrag=diba71e4kfo89v name=stream-c100bc70 epId=c100bc70 local_ufrag=diba71e4kfo89v] MergingDatagramSocket.close#142: Closing.
2020-03-29 20:09:32.334 INFO: [65] [confId=12965e6729766a64 epId=c100bc70 gid=ff5f5f stats_id=Edgardo-Uzb conf_name=testconf] Endpoint.expire#649: Expired.
2020-03-29 20:09:36.089 INFO: [18] Videobridge.createConference#326: create_conf, id=d664a4d81202a3d2 gid=null logging=false
2020-03-29 20:09:36.105 INFO: [18] Health.doRun#294: Performed a successful health check in 18ms. Sticky failure: false
2020-03-29 20:09:43.033 INFO: [17] VideobridgeExpireThread.expire#144: Running expire()
2020-03-29 20:09:43.033 INFO: [17] VideobridgeExpireThread.expire#150: Conference 12965e6729766a64 should expire, expiring it
2020-03-29 20:09:43.034 INFO: [120] [confId=12965e6729766a64 gid=ff5f5f conf_name=testconf] Conference.expire#527: Expiring.
2020-03-29 20:09:43.035 INFO: [120] [confId=12965e6729766a64 gid=ff5f5f conf_name=testconf] Conference.updateStatisticsOnExpire#610: expire_conf,duration=40,has_failed=false,has_partially_failed=false

I’ve done a bit more digging, and it appears from the coturn logs that I might be running into the situation covered in this thread:

185: IPv4. tcp or tls connected to: 127.0.0.1:42708
185: session 003000000000000001: TLS/TCP socket disconnected: 127.0.0.1:42708
185: session 003000000000000001: closed (2nd stage), user <> realm <jitsi.my.domain> origin <>, local 127.0.0.1:4445, remote 127.0.0.1:42708, reason: TLS/TCP socket buffer operation error (callback)

This occurs both when clients connect to coturn via nginx and directly through TCP 4445.