How to make unstable version great again after jicofo uncomponentization

Hello

last unstable change involves removing the use of component connection from jicofo to prosody. The deed is done in the prosody jitsi-meet debian post install, the prosody config for the focus component is changed from an external component:
Component “focus.myurl.mytld”
to an internal component:
Component “focus.myurl.mytld” “client_proxy”

now, since jicofo don’t connect anymore to the 5347 port of Prosody, how is it supposed to connect ? This has been carefully documented in the jicofo doc subdirectory.
Well, it does not, it’s just desperately knocking on port 5347 where Prosody don’t listen anymore.
So for the time being, while it would be great to connect with the new system - a very good idea by itself -, the easiest way I have found is to reverse the prosody config change and everything works again because Prosody listens on port 5347.

@Boris_Grozev

Well, jicofo uses the user connection which is already configured in jicofo.
Do you say that after the update you still see jicofo trying to connect to the component port?

Jicofo 2021-01-18 18:21:21.894 SEVERE: [24] org.jitsi.jicofo.xmpp.FocusComponent.log() java.net.ConnectException: Connection refused (Connection refused), host:localhost, port:5347
org.xmpp.component.ComponentException: java.net.ConnectException: Connection refused (Connection refused)
	at org.jivesoftware.whack.ExternalComponent.connect(ExternalComponent.java:296)
	at org.jivesoftware.whack.ExternalComponentManager.addComponent(ExternalComponentManager.java:242)
	at org.jivesoftware.whack.ExternalComponentManager.addComponent(ExternalComponentManager.java:222)
	at org.jitsi.jicofo.xmpp.FocusComponent$Connector.lambda$connect$0(FocusComponent.java:203)
	at org.jitsi.retry.RetryStrategy$TaskRunner.run(RetryStrategy.java:167)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:834)
Caused by: java.net.ConnectException: Connection refused (Connection refused)
	at java.base/java.net.PlainSocketImpl.socketConnect(Native Method)
	at java.base/java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:399)
	at java.base/java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:242)
	at java.base/java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:224)
	at java.base/java.net.SocksSocketImpl.connect(SocksSocketImpl.java:403)
	at java.base/java.net.Socket.connect(Socket.java:609)
	at org.jivesoftware.whack.ExternalComponent.connect(ExternalComponent.java:174)
	... 10 more

now I’m looking a bit more at this stuff, it seems that the connections errors are happening before I see any problem in fact; I’m using secure domain and it fails when I’m trying to authenticate
connection: GET_SESSION_ID error

the connections failure to port 5347 are happening before that, so possibly it could 2 unrelated problems - first problem, Jicofo is still trying to connect and spams the logs but it could be a cosmetic problem, second problem it does not work but only for secure domain and it may be an unrelated change, because I’m using secure domain - or because my server is behind a NAT (sort of).

Jan 18 18:47:45 focus.meeting.mydomain.mytld:client_proxy	debug	stanza to target: name = iq, type = set
Jan 18 18:47:45 focus.meeting.mydomain.mytld:client_proxy	debug	NAT-ed stanza: from: wx2t6-ztxbvmxsf6@guest.meeting.mydomain.mytld/MMHYbjeU -> focus.meeting.mydomain.mytld/wx2t6-ztxbvmxsf6@guest.meeting.mydomain.mytld/MMHYbjeU, to: focus.meeting.mydomain.mytld -> focus@auth.meeting.mydomain.mytld/focus
Jan 18 18:47:45 focus.meeting.mydomain.mytld:client_proxy	debug	received stanza from c2s session
Jan 18 18:47:45 focus.meeting.mydomain.mytld:client_proxy	debug	non-presence stanza from target: name = iq, type = error
Jan 18 18:47:45 focus.meeting.mydomain.mytld:client_proxy	debug	de-NAT-ed stanza: from: focus@auth.meeting.mydomain.mytld/focus -> focus.meeting.mydomain.mytld, to: focus.meeting.mydomain.mytld/wx2t6-ztxbvmxsf6@guest.meeting.mydomain.mytld/MMHYbjeU -> wx2t6-ztxbvmxsf6@guest.meeting.mydomain.mytld/MMHYbjeU
Jan 18 18:47:50 focus.meeting.mydomain.mytld:client_proxy	debug	received stanza from c2s session
Jan 18 18:47:50 focus.meeting.mydomain.mytld:client_proxy	debug	stanza to target: name = iq, type = set
Jan 18 18:47:50 focus.meeting.mydomain.mytld:client_proxy	debug	NAT-ed stanza: from: wx2t6-ztxbvmxsf6@guest.meeting.mydomain.mytld/MMHYbjeU -> focus.meeting.mydomain.mytld/wx2t6

Are you sure the port 5347 logs are from the latest jicofo from unstable?

yes, it’s even the last git tag at the moment.

dpkg -l | grep jicofo
ii jicofo 1.0-700-1 all JItsi Meet COnference FOcus

obviously the code for connecting as a component has not been removed since it works when I reconfigure prosody.

:man_facepalming: yes, it is not merged yet ref: Remove FocusComponent. by bgrozev · Pull Request #672 · jitsi/jicofo · GitHub

adding the patch makes the log spamming go away, but it does not fix the auth failure.

Jan 18 20:03:24 mod_bosh	debug	Handling new request table: 0x55668fd955b0: <body rid="1481149682" sid="720cd0ea-622e-4b07-8f91-4df0b10c5610" xmlns="http://jabber.org/protocol/httpbind"><iq id="415580d8-c262-4d25-bdd0-2480aa30af02:sendIQ" to="focus.meeting.myurl.mytld" type="set" xmlns="jabber:client"><conference machine-uid="82c50858b166f56334693a0fd9ab70b9" room="dugrabuge48@conference.meeting.myurl.mytld" xmlns="http://jitsi.org/protocol/focus"><property name="disableRtx" value="false"/></conference></iq></body>
----------
Jan 18 20:03:24 mod_bosh	debug	BOSH body open (sid: 720cd0ea-622e-4b07-8f91-4df0b10c5610)
Jan 18 20:03:24 bosh720cd0ea-622e-4b07-8f91-4df0b10c5610	debug	rid: 1481149682, sess: 1481149681, diff: 1
Jan 18 20:03:24 mod_bosh	debug	BOSH stanza received: <iq to='focus.meeting.myurl.mytld' id='415580d8-c262-4d25-bdd0-2480aa30af02:sendIQ' type='set'>

Jan 18 20:03:24 bosh720cd0ea-622e-4b07-8f91-4df0b10c5610	debug	Received[c2s]: <iq to='focus.meeting.myurl.mytld' id='415580d8-c262-4d25-bdd0-2480aa30af02:sendIQ' type='set'>
Jan 18 20:03:24 focus.meeting.myurl.mytld:client_proxy	debug	received stanza from c2s session
Jan 18 20:03:24 focus.meeting.myurl.mytld:client_proxy	debug	stanza to target: name = iq, type = set
Jan 18 20:03:24 focus.meeting.myurl.mytld:client_proxy	debug	NAT-ed stanza: from: 0dymdh4jjuyirplq@guest.meeting.myurl.mytld/L6e22dbv -> focus.meeting.myurl.mytld/0dymdh4jjuyirplq@guest.meeting.myurl.mytld/L6e22dbv, to: focus.meeting.myurl.mytld -> focus@auth.meeting.myurl.mytld/focus
Jan 18 20:03:24 c2s55668f945520	debug	Sending[c2s]: <iq to='focus@auth.meeting.myurl.mytld/focus' id='415580d8-c262-4d25-bdd0-2480aa30af02:sendIQ' type='set' from='focus.meeting.myurl.mytld/0dymdh4jjuyirplq@guest.meeting.myurl.mytld/L6e22dbv'>
Jan 18 20:03:24 mod_bosh	debug	Session 720cd0ea-622e-4b07-8f91-4df0b10c5610 has 2 out of 1 requests open
Jan 18 20:03:24 mod_bosh	debug	and there are 0 things in the send_buffer:
Jan 18 20:03:24 mod_bosh	debug	We are holding too many requests, so...
Jan 18 20:03:24 mod_bosh	debug	...sending an empty response
Jan 18 20:03:24 mod_bosh	debug	We have an open request, so sending on that
Jan 18 20:03:24 mod_bosh	debug	Request destroyed: table: 0x55668fd3c850
Jan 18 20:03:24 socket	debug	server.lua: closed client handler and removed socket from list
Jan 18 20:03:24 mod_bosh	debug	Have nothing to say, so leaving request unanswered for now
Jan 18 20:03:24 c2s55668f945520	debug	Received[c2s]: <iq to='focus.meeting.myurl.mytld/0dymdh4jjuyirplq@guest.meeting.myurl.mytld/L6e22dbv' id='415580d8-c262-4d25-bdd0-2480aa30af02:sendIQ' type='error'>
Jan 18 20:03:24 focus.meeting.myurl.mytld:client_proxy	debug	received stanza from c2s session
Jan 18 20:03:24 focus.meeting.myurl.mytld:client_proxy	debug	non-presence stanza from target: name = iq, type = error
Jan 18 20:03:24 focus.meeting.myurl.mytld:client_proxy	debug	de-NAT-ed stanza: from: focus@auth.meeting.myurl.mytld/focus -> focus.meeting.myurl.mytld, to: focus.meeting.myurl.mytld/0dymdh4jjuyirplq@guest.meeting.myurl.mytld/L6e22dbv -> 0dymdh4jjuyirplq@guest.meeting.myurl.mytld/L6e22dbv
Jan 18 20:03:24 mod_bosh	debug	We have an open request, so sending on that
Jan 18 20:03:24 mod_bosh	debug	Request destroyed: table: 0x55668ff66290
Jan 18 20:03:24 bosh720cd0ea-622e-4b07-8f91-4df0b10c5610	debug	BOSH session marked as inactive (for 60s)
Jan 18 20:03:24 socket	debug	server.lua: closed client handler and removed socket from list
Jan 18 20:03:24 socket	debug	server.lua: accepted new client connection from 127.0.0.1:48718 to 5290
Jan 18 20:03:24 http.server	debug	Firing event: POST /http-bind
Jan 18 20:03:24 mod_bosh	debug	Handling new request table: 0x556690152a70: <body rid="1481149683" sid="720cd0ea-622e-4b07-8f91-4df0b10c5610" xmlns="http://jabber.org/protocol/httpbind"/>
----------
Jan 18 20:03:24 mod_bosh	debug	BOSH body open (sid: 720cd0ea-622e-4b07-8f91-4df0b10c5610)
Jan 18 20:03:24 bosh720cd0ea-622e-4b07-8f91-4df0b10c5610	debug	rid: 1481149683, sess: 1481149682, diff: 1
Jan 18 20:03:24 mod_bosh	debug	Session 720cd0ea-622e-4b07-8f91-4df0b10c5610 has 1 out of 1 requests open
Jan 18 20:03:24 mod_bosh	debug	and there are 0 things in the send_buffer:
Jan 18 20:03:24 mod_bosh	debug	Have nothing to say, so leaving request unanswered for now

That seems incorrect. We will take a look.

We had some issues with the build system, so the PR that removed the component in jicofo was delayed. It is now merged, so the issue with the logs being spammed should be fixed.

The other problem you’re hitting is probably because of authentication. I’m working on a fix right now, let me know if you want to test it early.

Boris

thanks, if it can help you to validate the fix I’ll do it, otherwise it’s a test system I do not need a quick solution.

Well, I tested 703 and did not get much joy out of it. Same error message.
Here is a debug trace for prosody:

Jan 20 21:44:09 http.server     debug   Firing event: POST /http-bind
Jan 20 21:44:09 mod_bosh        debug   Handling new request table: 0x5622925576a0: <body rid="3202912773" sid="5a6a6e73-e9c3-42b6-b54a-5635182c5a6e" xmlns="http://jabber.org/protocol/httpbind"/>
----------
Jan 20 21:44:09 mod_bosh        debug   BOSH body open (sid: 5a6a6e73-e9c3-42b6-b54a-5635182c5a6e)
Jan 20 21:44:09 bosh5a6a6e73-e9c3-42b6-b54a-5635182c5a6e        debug   rid: 3202912773, sess: 3202912772, diff: 1
Jan 20 21:44:09 mod_bosh        debug   Session 5a6a6e73-e9c3-42b6-b54a-5635182c5a6e has 1 out of 1 requests open
Jan 20 21:44:09 mod_bosh        debug   and there are 0 things in the send_buffer:
Jan 20 21:44:09 mod_bosh        debug   Have nothing to say, so leaving request unanswered for now
Jan 20 21:44:12 c2s56229271baf0 debug   Received[c2s]: <presence to='jvbbrewery@internal.auth.meet.myurl.mytld/4326ee22-c910-42a2-9854-1af066e5d4fe' id='1C9Wi-860'>
Jan 20 21:44:12 auth.meet.myurl.mytld:pep debug   get_pep_service("jvb")
Jan 20 21:44:12 internal.auth.meet.myurl.mytld:muc        debug   presence update for jvbbrewery@internal.auth.meet.myurl.mytld/4326ee22-c910-42a2-9854-1af066e5d4fe from session jvb@auth.meet.myurl.mytld/Hx5DJL1P
Jan 20 21:44:12 c2s5622927b2c50 debug   Sending[c2s]: <presence to='focus@auth.meet.myurl.mytld/focus' id='1C9Wi-860' from='jvbbrewery@internal.auth.meet.myurl.mytld/4326ee22-c910-42a2-9854-1af066e5d4fe'>
Jan 20 21:44:12 c2s56229271baf0 debug   Sending[c2s]: <presence to='jvb@auth.meet.myurl.mytld/Hx5DJL1P' id='1C9Wi-860' from='jvbbrewery@internal.auth.meet.myurl.mytld/4326ee22-c910-42a2-9854-1af066e5d4fe'>
Jan 20 21:44:14 socket  debug   server.lua: accepted new client connection from 127.0.0.1:44140 to 5290
Jan 20 21:44:14 http.server     debug   Firing event: POST /http-bind
Jan 20 21:44:14 mod_bosh        debug   Handling new request table: 0x5622931bc750: <body rid="3202912774" sid="5a6a6e73-e9c3-42b6-b54a-5635182c5a6e" xmlns="http://jabber.org/protocol/httpbind"><iq id="ef87a946-88e3-4dc0-a7d8-0a280a92749b:sendIQ" to="focus.meet.myurl.mytld" type="set" xmlns="jabber:client"><conference machine-uid="84e9a69acca249391b8d5ea75af80d1b" room="veracitefausse31@conference.meet.myurl.mytld" xmlns="http://jitsi.org/protocol/focus"><property name="disableRtx" value="false"/></conference></iq></body>
----------
Jan 20 21:44:14 mod_bosh        debug   BOSH body open (sid: 5a6a6e73-e9c3-42b6-b54a-5635182c5a6e)
Jan 20 21:44:14 bosh5a6a6e73-e9c3-42b6-b54a-5635182c5a6e        debug   rid: 3202912774, sess: 3202912773, diff: 1
Jan 20 21:44:14 mod_bosh        debug   BOSH stanza received: <iq to='focus.meet.myurl.mytld' id='ef87a946-88e3-4dc0-a7d8-0a280a92749b:sendIQ' type='set'>

Jan 20 21:44:14 bosh5a6a6e73-e9c3-42b6-b54a-5635182c5a6e        debug   Received[c2s]: <iq to='focus.meet.myurl.mytld' id='ef87a946-88e3-4dc0-a7d8-0a280a92749b:sendIQ' type='set'>
Jan 20 21:44:14 focus.meet.myurl.mytld:client_proxy       debug   received stanza from c2s session
Jan 20 21:44:14 focus.meet.myurl.mytld:client_proxy       debug   stanza to target: name = iq, type = set
Jan 20 21:44:14 focus.meet.myurl.mytld:client_proxy       debug   NAT-ed stanza: from: 00_g4qxhzqwnj-ze@guest.meet.myurl.mytld/pyEkuJR8 -> focus.meet.myurl.mytld/00_g4qxhzqwnj-ze@guest.meet.myurl.mytld/pyEkuJR8, to: focus.meet.myurl.mytld -> focus@auth.meet.myurl.mytld/focus
Jan 20 21:44:14 c2s5622927b2c50 debug   Sending[c2s]: <iq to='focus@auth.meet.myurl.mytld/focus' type='set' id='ef87a946-88e3-4dc0-a7d8-0a280a92749b:sendIQ' from='focus.meet.myurl.mytld/00_g4qxhzqwnj-ze@guest.meet.myurl.mytld/pyEkuJR8'>
Jan 20 21:44:14 mod_bosh        debug   Session 5a6a6e73-e9c3-42b6-b54a-5635182c5a6e has 2 out of 1 requests open
Jan 20 21:44:14 mod_bosh        debug   and there are 0 things in the send_buffer:
Jan 20 21:44:14 mod_bosh        debug   We are holding too many requests, so...
Jan 20 21:44:14 mod_bosh        debug   ...sending an empty response
Jan 20 21:44:14 mod_bosh        debug   We have an open request, so sending on that
Jan 20 21:44:14 mod_bosh        debug   Request destroyed: table: 0x562291ff5090
Jan 20 21:44:14 socket  debug   server.lua: closed client handler and removed socket from list
Jan 20 21:44:14 mod_bosh        debug   Have nothing to say, so leaving request unanswered for now
Jan 20 21:44:14 c2s5622927b2c50 debug   Received[c2s]: <iq to='focus.meet.myurl.mytld/00_g4qxhzqwnj-ze@guest.meet.myurl.mytld/pyEkuJR8' id='ef87a946-88e3-4dc0-a7d8-0a280a92749b:sendIQ' type='error'>
Jan 20 21:44:14 focus.meet.myurl.mytld:client_proxy       debug   received stanza from c2s session
Jan 20 21:44:14 focus.meet.myurl.mytld:client_proxy       debug   non-presence stanza from target: name = iq, type = error

while the jicofo log is surprisingly silent

Jicofo 2021-01-20 21:44:08.465 INFO: [21] org.jitsi.health.HealthChecker.log() Performed a successful health check in PT0.024161S. Sticky failure: false
Jicofo 2021-01-20 21:44:08.918 INFO: [31] org.jitsi.jicofo.xmpp.ConferenceIqHandler.log() Focus request for room: veracitefausse31@conference.meet.myurl.mytld
Jicofo 2021-01-20 21:44:14.149 INFO: [31] org.jitsi.jicofo.xmpp.ConferenceIqHandler.log() Focus request for room: veracitefausse31@conference.meet.myurl.mytld
Jicofo 2021-01-20 21:44:18.461 INFO: [21] org.jitsi.health.HealthChecker.log() Performed a successful health check in PT0.020655S. Sticky failure: false
Jicofo 2021-01-20 21:44:28.463 INFO: [21] org.jitsi.health.HealthChecker.log() Performed a successful health check in PT0.022974S. Sticky failure: false
Jicofo 2021-01-20 21:44:38.459 INFO: [21] org.jitsi.health.HealthChecker.log() Performed a successful health check in PT0.018713S. Sticky failure: false
Jicofo 2021-01-20 21:44:48.463 INFO: [21] org.jitsi.health.HealthChecker.log() Performed a successful health check in PT0.022122S. Sticky failure: false
Jicofo 2021-01-20 21:44:58.464 INFO: [21] org.jitsi.health.HealthChecker.log() Performed a successful health check in PT0.023721S. Sticky failure: false
Jicofo 2021-01-20 21:45:04.224 INFO: [31] org.jitsi.jicofo.xmpp.ConferenceIqHandler.log() Focus request for room: veracitefausse47@conference.meet.myurl.mytld
Jicofo 2021-01-20 21:45:08.463 INFO: [21] org.jitsi.health.HealthChecker.log() Performed a successful health check in PT0.022614S. Sticky failure: false
Jicofo 2021-01-20 21:45:09.302 INFO: [31] org.jitsi.jicofo.xmpp.ConferenceIqHandler.log() Focus request for room: veracitefausse47@conference.meet.myurl.mytld
Jicofo 2021-01-20 21:45:09.677 INFO: [31] org.jitsi.jicofo.xmpp.ConferenceIqHandler.log() Focus request for room: veracitefausse47@conference.meet.myurl.mytld
Jicofo 2021-01-20 21:45:14.946 INFO: [31] org.jitsi.jicofo.xmpp.ConferenceIqHandler.log() Focus request for room: veracitefausse47@conference.meet.myurl.mytld
Jicofo 2021-01-20 21:45:18.462 INFO: [21] org.jitsi.health.HealthChecker.log() Performed a successful health check in PT0.022394S. Sticky failure: false
Jicofo 2021-01-20 21:45:20.207 INFO: [31] org.jitsi.jicofo.xmpp.ConferenceIqHandler.log() Focus request for room: veracitefausse47@conference.meet.myurl.mytld
Jicofo 2021-01-20 21:45:25.493 INFO: [31] org.jitsi.jicofo.xmpp.ConferenceIqHandler.log() Focus request for room: veracitefausse47@conference.meet.myurl.mytld
Jicofo 2021-01-20 21:45:28.462 INFO: [21] org.jitsi.health.HealthChecker.log() Performed a successful health check in PT0.02172S. Sticky failure: false

That’s it, MUGA !

diff -ru /var/lib/dpkg/info/jicofo.postinst.ori /var/lib/dpkg/info/jicofo.postinst
--- /var/lib/dpkg/info/jicofo.postinst.ori	2021-01-22 23:15:12.000000000 +0100
+++ /var/lib/dpkg/info/jicofo.postinst	2021-01-25 13:10:30.721025610 +0100
@@ -115,7 +115,7 @@
         fi
 
         # Make sure the client-proxy is set correctly.
-        hocon -f $HOCON_CONFIG set xmpp.client.client-proxy "focus.$JVB_HOSTNAME"
+        hocon -f $HOCON_CONFIG set jicofo.xmpp.client.client-proxy "focus.$JVB_HOSTNAME"
 
         # we don't want to start the daemon as root
         if ! getent group jitsi > /dev/null ; then

I love your comments, @Boris_Grozev.