Smack 4.4.7: Sending of muc#roomconfig form always failed with NoResponseException even the server reply within ms after IQ-set is received

[cmeng]

During aTalk testing, it is found that sending of muc#roomconfig FORM stanza always failed with NoResponseException even the xmpp server replied IQ-result within ms of the IQ-set received.
The test carried out are on the same home network using WiFi.

Below is a log info captured of the whole IQ exchanges process on aTalk and XMPP ejabberd server.
It is seen that the IQ-result received by aTalk always appear only after the NoResponseException; independent of the Smack Reply Timer set e.g. 5-Sec, 10-Sec and 30-Sec.

From ejabberd log, the xmpp server actually returns IQ-result within ms of the received IQ-set; and is well within the smack timeout i.e.: server sends on 07:50:52.217… but aTalk smack timeout on 07:51:03.596.

Note there is time lead of ejabberd on aTalk in IQ send and receive by ejabberd server ~0.6s;
(07:50:53.591 - 07:50:52.203…); likely due to logcat message display delay on aTalk. Both aTalk and server clocks are synced with internet time.

Any comment?

// ============= aTalk logcat info ============ //
07:50:53.581  D  Sending room config form!!!
07:50:53.591  D  SENT (1): 
                 <iq to='chatroom3@conference.atalk.sytes.net' id='XY69C-37' type='set'>
                   <query xmlns='http://jabber.org/protocol/muc#owner'>
                     <x xmlns='jabber:x:data' type='submit'>
                       <field var='FORM_TYPE'>
                         <value>
                           http://jabber.org/protocol/muc#roomconfig
                         </value>
                       </field>
                     </x>
                   </query>
                 </iq>
                 <r xmlns='urn:xmpp:sm:3'/>
                 
07:51:03.596  E  Failed to send config form.
                 org.jivesoftware.smack.SmackException$NoResponseException: No response received within reply timeout. Timeout was 10000ms (~10s). StanzaCollector has been cancelled. Waited for response using: IQReplyFilter: iqAndIdFilter (AndFilter: (OrFilter: (IQTypeFilter: type=error, IQTypeFilter: type=result), StanzaIdFilter: id=XY69C-37)), : fromFilter (OrFilter: (FromMatchesFilter (full): chatroom3@conference.atalk.sytes.net)).
                 	at org.jivesoftware.smack.StanzaCollector.nextResultOrThrow(StanzaCollector.java:281)
                 	at org.jivesoftware.smack.StanzaCollector.nextResultOrThrow(StanzaCollector.java:228)
                 	at org.jivesoftware.smackx.muc.MultiUserChat.sendConfigurationForm(MultiUserChat.java:873)
                 	at net.java.sip.communicator.impl.protocol.jabber.ChatRoomJabberImpl$ParticipantListener.processOwnPresence(ChatRoomJabberImpl.java:2771)
                 	at net.java.sip.communicator.impl.protocol.jabber.ChatRoomJabberImpl$ParticipantListener.processPresence(ChatRoomJabberImpl.java:2744)
                 	at org.jivesoftware.smackx.muc.MultiUserChat$3.processStanza(MultiUserChat.java:309)
                 	at org.jivesoftware.smack.AbstractXMPPConnection.lambda$invokeStanzaCollectorsAndNotifyRecvListeners$8(AbstractXMPPConnection.java:1619)
                 	at org.jivesoftware.smack.AbstractXMPPConnection$$ExternalSyntheticLambda3.run(Unknown Source:6)
                 	at org.jivesoftware.smack.AbstractXMPPConnection$10.run(AbstractXMPPConnection.java:2149)
                 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
                 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
                 	at java.lang.Thread.run(Thread.java:920)
                 	
07:51:03.667  D  RECV (1): 
                 <iq xml:lang='en-US' to='swordfish@atalk.sytes.net/atalk' from='chatroom3@conference.atalk.sytes.net' type='result' id='XY69C-37'/>                 	


// ============= ejabberd log info ============ //
07:50:52.203612+08:00 [notice] (tls|<0.624.0>) Received XML on stream = "<iq to='chatroom3@conference.atalk.sytes.net' id='XY69C-37' type='set'><query xmlns='http://jabber.org/protocol/muc#owner'><x xmlns='jabber:x:data' type='submit'><field var='FORM_TYPE'><value>http://jabber.org/protocol/muc#roomconfig</value></field></x></query></iq><r xmlns='urn:xmpp:sm:3'/>"

07:50:52.217373+08:00 [notice] (tls|<0.624.0>) Send XML on stream = "<iq xml:lang='en-US' to='swordfish@atalk.sytes.net/atalk' from='chatroom3@conference.atalk.sytes.net' type='result' id='XY69C-37'/>"

[cmeng]

Found the following change fixes the problem.

Early on, the sending of muc#roomconfig FORM is processed within the
PresenceListener#processOwnPresence(Presence presence) using the same thread. This seems to cause NoResponseException.

After moving and execute the muc#roomconfig FORM sending in a new Thread() as shown in the code below, the problem is resolved.

        /**
         * Processes a <code>Presence</code> packet addressed to our own occupant JID.
         * with either MUCUser extension or MUCInitialPresence extension (error)
         *
         * @param presence the packet to process.
         */
        private void processOwnPresence(Presence presence) {
            MUCUser mucUser = presence.getExtension(MUCUser.class);
            if (mucUser != null) {
                // lastPresenceSent = presence;
                MUCAffiliation affiliation = mucUser.getItem().getAffiliation();
                MUCRole role = mucUser.getItem().getRole();

                // if status 201 is available means that room is created and locked till we send the configuration
                if ((mucUser.getStatus() != null)
                        && mucUser.getStatus().contains(MUCUser.Status.ROOM_CREATED_201)) {
                    new Thread() {
                        @Override
                        public void run() {
                            try {
                                TextSingleFormField formField
                                        = FormField.buildHiddenFormType("http://jabber.org/protocol/muc#roomconfig");
                                DataForm dataForm = DataForm.builder(DataForm.Type.form).addField(formField).build();
                                mMultiUserChat.sendConfigurationForm(new FillableForm(dataForm));

                                // Sending null also picked up the options OperationSetMultiUserChatJabberImpl#createChatRoom and sent
                                // mMultiUserChat.sendConfigurationForm(null);
                            } catch (XMPPException | NoResponseException | NotConnectedException |
                                     InterruptedException e) {
                                Timber.e(e, "Failed to send config form.");
                            }
                        }
                    }.start();

                    // Update mNickName here as it is used in fireLocalUserRoleEvent before joinAs() is triggered.
                    EntityFullJid from = presence.getFrom().asEntityFullJidIfPossible();
                    mNickName = from.getResourceOrEmpty();

                    opSetMuc.addSmackInvitationRejectionListener(mMultiUserChat, ChatRoomJabberImpl.this);
                    if (affiliation == MUCAffiliation.owner) {
                        setLocalUserRole(ChatRoomMemberRole.OWNER, true);
                    }
                    else {
                        setLocalUserRole(ChatRoomMemberRole.MODERATOR, true);
                    }
                }
                else {
                    // this is the presence for our own initial mRole and affiliation,
                    // as smack do not fire any initial events lets check it and fire events
                    if (role == MUCRole.moderator
                            || affiliation == MUCAffiliation.owner
                            || affiliation == MUCAffiliation.admin) {
                        ChatRoomMemberRole scRole = ChatRoomJabberImpl.smackRoleToScRole(role, affiliation);
                        setLocalUserRole(scRole, true);
                    }

                    if (!presence.isAvailable() && role == MUCRole.none
                            && affiliation == MUCAffiliation.none) {
                        Destroy destroy = mucUser.getDestroy();

                        // the room is unavailable to us, there is no message we will just leave
                        if (destroy == null) {
                            leave();
                        }
                        else {
                            leave(destroy.getJid(), aTalkApp.getResString(R.string.service_gui_CHATROOM_DESTROY_MESSAGE,
                                    destroy.getReason()));
                        }
                    }
                }
            }
            // Check for presence error (which use MUCInitialPresence extension)
            else if (Presence.Type.error == presence.getType()) {
                String errMessage = presence.getError().toString();
                addMessage(errMessage, ChatMessage.MESSAGE_ERROR);
            }
        }

[Flow]

This is basically the same issue as in Thread stuck in MultiUserChat.enter() forever - #15 by Flow

You are performing a blocking operation in a synchronous listener, which creates a deadlock that is resolved once the blocking operation times out.

Probably somewhere at

             at net.java.sip.communicator.impl.protocol.jabber.ChatRoomJabberImpl$ParticipantListener.processOwnPresence(ChatRoomJabberImpl.java:2771)
             at net.java.sip.communicator.impl.protocol.jabber.ChatRoomJabberImpl$ParticipantListener.processPresence(ChatRoomJabberImpl.java:2744)

which is within the listener, the room join should be decoupled from the listener’s control flow. Alternatively, use an asynchronous listener.