No traffic to JVB from client

Hi!

I’m in the process of integrating jitsi meet within my environment (external coturn servers and ejabberd 20.04). I get no a/v when using the JVB (p2p disabled).

So far I managed to have jicofo and jvb connect to my external ejabberd server and join the jvbbrewery room. JVB is hosted in it’s own VM. I can see the focus user as well as the JVB inside the MUC. So far so good.

I learned that JVB/Jicofo currently don’t like Ejabberd + TURN:

So far, no problem. JVB 10000/udp should be fine as the clients are currently not behind restrictive firewalls. TCP-harvester is disabled as I want UDP to work first.

Problem is: I never receive a single packet on 10000/udp on JVB server (firewall disabled) and according to the browsers console, Jitsi Web tries a TURN fallback using XMPP which failes (mentioned issue 5786).

I had a talk on the ejabberd channel and was told, that 10000/udp should be the first media channel a participant would try. How can I debug this? It clearly is not the case, which means something is going wrong here. Java is listening on this port and there are no errors in the log, only some warnings about presence on jicofo which are fine.

Kind regards

I can see the advertisement of the JVB in my clients console but Chrome never connects to this server.
Immediately after the offer I get this:

2020-07-16T14:30:55.371Z [modules/xmpp/strophe.jingle.js] <g.onJingle>: Marking session from test1@conference.meet.example.net/meet-focus as P2P

2020-07-16T14:30:55.372Z [JitsiMeetJS.js] <Object.getGlobalOnErrorHandler>: UnhandledError: null Script: null Line: null Column: null StackTrace: Error: P2P mode disabled in the configuration at se._rejectIncomingCall (JitsiConference.js:2011) at se._onIncomingCallP2P (JitsiConference.js:1829) at se.onIncomingCall (JitsiConference.js:1844) at a.emit (events.js:146) at g.onJingle (strophe.jingle.js:171) at I.Handler.run (strophe.umd.js:1875) at strophe.umd.js:3157 at Object.forEachChild (strophe.umd.js:830) at I.Connection._dataRecv (strophe.umd.js:3146) at D.Bosh._onRequestStateChange (strophe.umd.js:5012)

Not sure about the JS error, but if you could attach jvb logs we can see if there’s anything on that side.

From my JVB host:

2020-07-16 22:09:47.164 INFO: [19] VideobridgeExpireThread.expire#144: Running expire()
2020-07-16 22:09:47.164 INFO: [19] VideobridgeExpireThread.expire#150: Conference b99abd90e4051f33 should expire, expiring it
2020-07-16 22:09:47.166 INFO: [51] [confId=b99abd90e4051f33 gid=ffe6af conf_name=test5] Conference.expire#527: Expiring.
2020-07-16 22:09:47.167 INFO: [51] [confId=b99abd90e4051f33 gid=ffe6af conf_name=test5] Conference.updateStatisticsOnExpire#610: expire_conf,duration=79,has_failed=false,has_partially_failed=false
2020-07-16 22:09:47.875 INFO: [21] Videobridge.createConference#320: create_conf, id=2d51b267e3416cfe gid=null logging=false
2020-07-16 22:09:47.883 INFO: [21] AbstractHealthCheckService.run#171: Performed a successful health check in PT0.008091S. Sticky failure: false
2020-07-16 22:09:53.913 INFO: [28] Videobridge.createConference#320: create_conf, id=e1bc53a32713346d gid=ffe369 logging=true
2020-07-16 22:09:53.916 INFO: [28] [confId=e1bc53a32713346d epId=11100378 local_ufrag=fnk5r1edcjupfs gid=ffe369 conf_name=test5 ufrag=fnk5r1edcjupfs] Agent.gatherCandidates#662: Gathering candidates for component stream-11100378.RTP.
2020-07-16 22:09:53.917 INFO: [33] [confId=e1bc53a32713346d gid=ffe369 conf_name=test5] Conference.dominantSpeakerChanged#446: ds_change ds_id=11100378
2020-07-16 22:09:53.922 INFO: [28] [confId=e1bc53a32713346d epId=11100378 gid=ffe369 conf_name=test5] Endpoint.lambda$setTransportInfo$8#1110: Ignoring empty DtlsFingerprint extension:
2020-07-16 22:09:53.923 INFO: [28] [confId=e1bc53a32713346d epId=11100378 gid=ffe369 conf_name=test5] Endpoint.describe#1293: Transport description:
E0:33:DE:E3:95:8A:D8:0F:0B:0E:D4:D0:C6:EE:1A:81:1A:E1:BD:A3:3B:85:31:EB:7E:CC:2E:04:EA:E3:B5:1A
2020-07-16 22:09:53.937 INFO: [28] [confId=e1bc53a32713346d epId=14851749 local_ufrag=38q511edcjupgh gid=ffe369 conf_name=test5 ufrag=38q511edcjupgh] Agent.gatherCandidates#662: Gathering candidates for component stream-14851749.RTP.
2020-07-16 22:09:53.941 INFO: [28] [confId=e1bc53a32713346d epId=14851749 gid=ffe369 conf_name=test5] Endpoint.lambda$setTransportInfo$8#1110: Ignoring empty DtlsFingerprint extension:
2020-07-16 22:09:53.942 INFO: [28] [confId=e1bc53a32713346d epId=14851749 gid=ffe369 conf_name=test5] Endpoint.describe#1293: Transport description:
E0:33:DE:E3:95:8A:D8:0F:0B:0E:D4:D0:C6:EE:1A:81:1A:E1:BD:A3:3B:85:31:EB:7E:CC:2E:04:EA:E3:B5:1A
2020-07-16 22:09:55.645 INFO: [28] [confId=e1bc53a32713346d epId=10818819 local_ufrag=18jko1edcjur5t gid=ffe369 conf_name=test5 ufrag=18jko1edcjur5t] Agent.gatherCandidates#662: Gathering candidates for component stream-10818819.RTP.
2020-07-16 22:09:55.650 INFO: [28] [confId=e1bc53a32713346d epId=10818819 gid=ffe369 conf_name=test5] Endpoint.lambda$setTransportInfo$8#1110: Ignoring empty DtlsFingerprint extension:
2020-07-16 22:09:55.650 INFO: [28] [confId=e1bc53a32713346d epId=10818819 gid=ffe369 conf_name=test5] Endpoint.describe#1293: Transport description:
E0:33:DE:E3:95:8A:D8:0F:0B:0E:D4:D0:C6:EE:1A:81:1A:E1:BD:A3:3B:85:31:EB:7E:CC:2E:04:EA:E3:B5:1A
2020-07-16 22:09:57.876 INFO: [21] Videobridge.createConference#320: create_conf, id=f6dbbd05cfbb2481 gid=null logging=false
2020-07-16 22:09:57.883 INFO: [21] AbstractHealthCheckService.run#171: Performed a successful health check in PT0.008137S. Sticky failure: false
2020-07-16 22:10:07.876 INFO: [21] Videobridge.createConference#320: create_conf, id=58fe9d77e987fcda gid=null logging=false
2020-07-16 22:10:07.883 INFO: [21] AbstractHealthCheckService.run#171: Performed a successful health check in PT0.007871S. Sticky failure: false

I can see this XMPP stanza in my browser console, which means BOSH correctly forwards it.
The JVB-VM still does not receive a single packet from the source host (tried icmp and telnet and packets are logged immediately).

I don’t see anything about ICE in those logs…maybe it’s later. But you’d want to check that ICE started and connected successfully.

How do I do this? There are no other rows in the log, just my quotes.

Looking again I do see some ICE logs there, but that can’t be the entire log. Can you just attach the jvb log files? Ideally stop jvb, delete the logs, start jvb, repro the problem, then grab the file(s).

Here it is :slight_smile:
jvb.log (11.8 KB)

This log looks odd. Are you using Jicofo? Is this a custom client?

Yes, thats mandatory, isn’t it?
Log seems to be fine and the MUCs are created as I can join them using my XMPP client (I can also exchange chat messages).

No, it’s a fresh system running nginx and the jitsi-web package as well as jicofo. Just the bridge has it’s own host as I want to scale this system as soon as it works.

The only important change is that I use ejabberd instead of prosody and thus can not use TURN (which should not be needed for JVB).

I was just surprised at how little logging there was, but after checking there aren’t logs in some places I expected them (like creating an endpoint) and some are on debug. ICE definitely isn’t running, let’s try and up the log level to DEBUG to see what shows up there.

Can you set .level=FINE in the logging.properties file, restart JVB, and grab the logs after trying again?

Please see attached:
jvb.log (602.5 KB)

I thank you very much for your efforts!

I think this is your issue, no ICE ufrag/pw:

2020-07-17 01:26:19.139 FINE: [28] [confId=e5eddf3898ed0307 epId=34279752 local_ufrag=25pi31edcv6efn gid=ffcf12 conf_name=test5] IceTransport.startConnectivityEstablishment#141: Starting ICE connectivity establishment
2020-07-17 01:26:19.139 FINE: [28] [confId=e5eddf3898ed0307 epId=34279752 local_ufrag=25pi31edcv6efn gid=ffcf12 conf_name=test5] IceTransport.startConnectivityEstablishment#185: Not starting ICE, no ufrag and pwd yet.

I don’t know why this would happen since you’re using Jicofo and the stock client. Maybe something about ejabberd could mess that up, I dunno.

Ok but I’m not the only one using ejabberd. Many do, at least there are many tutorials and this installation is also using it:

They use hard-coded turn credentials. For testing purposes I copied that setting (nobody else is able to use my instance because of authentications, just me).

Ejabberd is very complex and I don’t know where to look in this case.

I read the docs over and over but I don’t see my configuration error.
According to XEP-0166, jingle sessions like jitsi uses needs no server support and I can see those messages in my browsers console.
My knowledge of xmpp is extensible but I’m expert for SIP and videobridge2 looks like a B2BUA (in SIP terms) and that would lead me to the assumption that it generated the SDP and thus is responsible for ufrag / pwd and not ejabberd. Jingle just uses XMPP as transport for the negotiation.

I agree, I don’t see how/why using ejabberd would effect this…it could be a red herring and something else could be going wrong. So you could start by looking at–I think–the session-accept message from the client to see if it has that information. You may need to turn on smack debugging to show the XMPP messages in Jicofo.

Ok, I will try that tomorrow. Today, with help from Holger@Ejabberd, I fetched a debug log from ejabberd. At least I did not find any error during the meeting.

https://pastebin.com/raw/vhumxkhn

Immediately after the P2P error, the session reaches session-terminate. I still do not understand why Jitsi tries P2P while it’s disabled:

Maybe the session gets taken down so fast, JVB does not even come into play.

Hmm, yeah that’s weird. @Pawel_Domas does that client log make sense to you? It looks like it tries p2p even though it’s disabled?

1 Like

What else can I try?

So the problem is that the client thinks that ‘session-initiate’ coming from Jicofo is not from a Jicofo, but regular client, thinks it’s a P2P connection and rejects it. Probably caused by this check returning false: https://github.com/jitsi/lib-jitsi-meet/blob/master/modules/xmpp/strophe.jingle.js#L130

1 Like