Bug in openfire 3.6.0 - Closing connection due to error while processing message: <iq type='result'

in openfire 3.6.0

2008.08.27 18:26:25 [org.jivesoftware.openfire.nio.ConnectionHandler.messageReceived(ConnectionHand ler.java:135)] Closing connection due to error while processing message: <iq type=‘result’ to=’—removed—>Pidgin2.5.0 (libpurple 2.5.0)
java.lang.NullPointerException
at java.util.concurrent.ConcurrentHashMap.remove(ConcurrentHashMap.java:919)
at org.jivesoftware.openfire.IQRouter.handle(IQRouter.java:284)
at org.jivesoftware.openfire.IQRouter.route(IQRouter.java:101)
at org.jivesoftware.openfire.spi.PacketRouterImpl.route(PacketRouterImpl.java:68)
at org.jivesoftware.openfire.net.StanzaHandler.processIQ(StanzaHandler.java:311)
at org.jivesoftware.openfire.net.ClientStanzaHandler.processIQ(ClientStanzaHandler .java:79)
at org.jivesoftware.openfire.net.StanzaHandler.process(StanzaHandler.java:276)
at org.jivesoftware.openfire.net.StanzaHandler.process(StanzaHandler.java:175)
at org.jivesoftware.openfire.nio.ConnectionHandler.messageReceived(ConnectionHandl er.java:133)
at org.apache.mina.common.support.AbstractIoFilterChain$TailFilter.messageReceived (AbstractIoFilterChain.java:570)
at org.apache.mina.common.support.AbstractIoFilterChain.callNextMessageReceived(Ab stractIoFilterChain.java:299)
at org.apache.mina.common.support.AbstractIoFilterChain.access$1100(AbstractIoFilt erChain.java:53)
at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.messageReceive d(AbstractIoFilterChain.java:648)
at org.apache.mina.common.IoFilterAdapter.messageReceived(IoFilterAdapter.java:80)
at org.apache.mina.common.support.AbstractIoFilterChain.callNextMessageReceived(Ab stractIoFilterChain.java:299)
at org.apache.mina.common.support.AbstractIoFilterChain.access$1100(AbstractIoFilt erChain.java:53)
at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.messageReceive d(AbstractIoFilterChain.java:648)
at org.apache.mina.filter.codec.support.SimpleProtocolDecoderOutput.flush(SimplePr otocolDecoderOutput.java:58)
at org.apache.mina.filter.codec.ProtocolCodecFilter.messageReceived(ProtocolCodecF ilter.java:185)
at org.apache.mina.common.support.AbstractIoFilterChain.callNextMessageReceived(Ab stractIoFilterChain.java:299)
at org.apache.mina.common.support.AbstractIoFilterChain.access$1100(AbstractIoFilt erChain.java:53)
at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.messageReceive d(AbstractIoFilterChain.java:648)
at org.apache.mina.filter.executor.ExecutorFilter.processEvent(ExecutorFilter.java :239)
at org.apache.mina.filter.executor.ExecutorFilter$ProcessEventsRunnable.run(Execut orFilter.java:283)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java: 885)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:51)
at java.lang.Thread.run(Thread.java:619)

Still there in 3.6.0a

A big bunch of my users are being disconnected permanently :-/

2008.08.30 19:33:18 [org.jivesoftware.openfire.nio.ConnectionHandler.messageReceived(ConnectionHand ler.java:135)] Closing connection due to error while processing message:

Psi
0.9.2
Windows XP


java.lang.NullPointerException
at java.util.concurrent.ConcurrentHashMap.remove(ConcurrentHashMap.java:922)
at org.jivesoftware.openfire.IQRouter.handle(IQRouter.java:284)
at org.jivesoftware.openfire.IQRouter.route(IQRouter.java:101)
at org.jivesoftware.openfire.spi.PacketRouterImpl.route(PacketRouterImpl.java:68)
at org.jivesoftware.openfire.net.StanzaHandler.processIQ(StanzaHandler.java:311)
at org.jivesoftware.openfire.net.ClientStanzaHandler.processIQ(ClientStanzaHandler .java:79)
at org.jivesoftware.openfire.net.StanzaHandler.process(StanzaHandler.java:276)
at org.jivesoftware.openfire.net.StanzaHandler.process(StanzaHandler.java:175)
at org.jivesoftware.openfire.nio.ConnectionHandler.messageReceived(ConnectionHandl er.java:133)
at org.apache.mina.common.support.AbstractIoFilterChain$TailFilter.messageReceived (AbstractIoFilterChain.java:570)
at org.apache.mina.common.support.AbstractIoFilterChain.callNextMessageReceived(Ab stractIoFilterChain.java:299)
at org.apache.mina.common.support.AbstractIoFilterChain.access$1100(AbstractIoFilt erChain.java:53)
at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.messageReceive d(AbstractIoFilterChain.java:648)
at org.apache.mina.common.IoFilterAdapter.messageReceived(IoFilterAdapter.java:80)
at org.apache.mina.common.support.AbstractIoFilterChain.callNextMessageReceived(Ab stractIoFilterChain.java:299)
at org.apache.mina.common.support.AbstractIoFilterChain.access$1100(AbstractIoFilt erChain.java:53)
at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.messageReceive d(AbstractIoFilterChain.java:648)
at org.apache.mina.filter.codec.support.SimpleProtocolDecoderOutput.flush(SimplePr otocolDecoderOutput.java:58)
at org.apache.mina.filter.codec.ProtocolCodecFilter.messageReceived(ProtocolCodecF ilter.java:185)
at org.apache.mina.common.support.AbstractIoFilterChain.callNextMessageReceived(Ab stractIoFilterChain.java:299)
at org.apache.mina.common.support.AbstractIoFilterChain.access$1100(AbstractIoFilt erChain.java:53)
at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.messageReceive d(AbstractIoFilterChain.java:648)
at org.apache.mina.common.IoFilterAdapter.messageReceived(IoFilterAdapter.java:80)
at org.jivesoftware.openfire.plugin.RawPrintFilter.messageReceived(RawPrintFilter. java:57)
at org.apache.mina.common.support.AbstractIoFilterChain.callNextMessageReceived(Ab stractIoFilterChain.java:299)
at org.apache.mina.common.support.AbstractIoFilterChain.access$1100(AbstractIoFilt erChain.java:53)
at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.messageReceive d(AbstractIoFilterChain.java:648)
at org.apache.mina.filter.executor.ExecutorFilter.processEvent(ExecutorFilter.java :239)
at org.apache.mina.filter.executor.ExecutorFilter$ProcessEventsRunnable.run(Execut orFilter.java:283)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java: 885)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:51)
at java.lang.Thread.run(Thread.java:619)
2008.08.30 19:33:18 [org.jivesoftware.openfire.nio.ConnectionHandler.messageReceived(ConnectionHand ler.java:135)] Closing connection due to error while processing message:

Psi
0.9.2
Windows XP


java.lang.NullPointerException
at java.util.concurrent.ConcurrentHashMap.remove(ConcurrentHashMap.java:922)
at org.jivesoftware.openfire.IQRouter.handle(IQRouter.java:284)
at org.jivesoftware.openfire.IQRouter.route(IQRouter.java:101)
at org.jivesoftware.openfire.spi.PacketRouterImpl.route(PacketRouterImpl.java:68)
at org.jivesoftware.openfire.net.StanzaHandler.processIQ(StanzaHandler.java:311)
at org.jivesoftware.openfire.net.ClientStanzaHandler.processIQ(ClientStanzaHandler .java:79)
at org.jivesoftware.openfire.net.StanzaHandler.process(StanzaHandler.java:276)
at org.jivesoftware.openfire.net.StanzaHandler.process(StanzaHandler.java:175)
at org.jivesoftware.openfire.nio.ConnectionHandler.messageReceived(ConnectionHandl er.java:133)
at org.apache.mina.common.support.AbstractIoFilterChain$TailFilter.messageReceived (AbstractIoFilterChain.java:570)
at org.apache.mina.common.support.AbstractIoFilterChain.callNextMessageReceived(Ab stractIoFilterChain.java:299)
at org.apache.mina.common.support.AbstractIoFilterChain.access$1100(AbstractIoFilt erChain.java:53)
at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.messageReceive d(AbstractIoFilterChain.java:648)
at org.apache.mina.common.IoFilterAdapter.messageReceived(IoFilterAdapter.java:80)
at org.apache.mina.common.support.AbstractIoFilterChain.callNextMessageReceived(Ab stractIoFilterChain.java:299)
at org.apache.mina.common.support.AbstractIoFilterChain.access$1100(AbstractIoFilt erChain.java:53)
at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.messageReceive d(AbstractIoFilterChain.java:648)
at org.apache.mina.filter.codec.support.SimpleProtocolDecoderOutput.flush(SimplePr otocolDecoderOutput.java:58)
at org.apache.mina.filter.codec.ProtocolCodecFilter.messageReceived(ProtocolCodecF ilter.java:185)
at org.apache.mina.common.support.AbstractIoFilterChain.callNextMessageReceived(Ab stractIoFilterChain.java:299)
at org.apache.mina.common.support.AbstractIoFilterChain.access$1100(AbstractIoFilt erChain.java:53)
at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.messageReceive d(AbstractIoFilterChain.java:648)
at org.apache.mina.common.IoFilterAdapter.messageReceived(IoFilterAdapter.java:80)
at org.jivesoftware.openfire.plugin.RawPrintFilter.messageReceived(RawPrintFilter. java:57)
at org.apache.mina.common.support.AbstractIoFilterChain.callNextMessageReceived(Ab stractIoFilterChain.java:299)
at org.apache.mina.common.support.AbstractIoFilterChain.access$1100(AbstractIoFilt erChain.java:53)
at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.messageReceive d(AbstractIoFilterChain.java:648)
at org.apache.mina.filter.executor.ExecutorFilter.processEvent(ExecutorFilter.java :239)
at org.apache.mina.filter.executor.ExecutorFilter$ProcessEventsRunnable.run(Execut orFilter.java:283)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java: 885)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:51)
at java.lang.Thread.run(Thread.java:619)

I had to rollback to 3.4 because of this issue.

All of my users were being disconnected continuously.

This seems like a fairly serious regression - is anything been done to look into it ?

Regards

Cameron

Hi, I have updated this morning from OF 3.5.2 to OF 3.6.0a and can confirm this problem now. I got many of this errors while the users thried to connect again.

2008.09.09 12:21:42 [org.jivesoftware.openfire.nio.ConnectionHandler.messageReceived(ConnectionHandler.java:135)] Closing connection due to error while processing message: iq type='result' to='***@jabber.thef0rce.org/Miranda'><query xmlns='jabber:iq:version'><name>Adium</name><version>1.3.1 (libpurple 2.5.1devel)</version></query></iq>java.lang.NullPointerException
        at java.util.concurrent.ConcurrentHashMap.remove(ConcurrentHashMap.java:922)
        at org.jivesoftware.openfire.IQRouter.handle(IQRouter.java:284)
        at org.jivesoftware.openfire.IQRouter.route(IQRouter.java:101)
        at org.jivesoftware.openfire.spi.PacketRouterImpl.route(PacketRouterImpl.java:68)
        at org.jivesoftware.openfire.net.StanzaHandler.processIQ(StanzaHandler.java:311)
        at org.jivesoftware.openfire.net.ClientStanzaHandler.processIQ(ClientStanzaHandler.java:79)
        at org.jivesoftware.openfire.net.StanzaHandler.process(StanzaHandler.java:276)
        at org.jivesoftware.openfire.net.StanzaHandler.process(StanzaHandler.java:175)
        at org.jivesoftware.openfire.nio.ConnectionHandler.messageReceived(ConnectionHandler.java:133) ... 2008.09.09 12:37:03 [org.jivesoftware.openfire.nio.ConnectionHandler.messageReceived(ConnectionHandler.java:135)] Closing connection due to error while processing message: <iq  xmlns="jabber:client" type="result" to="***@jab.twooit.com/Miranda" >
<query xmlns="jabber:iq:version">
<name>Psi</name>
<version>0.12</version>
<os>Windows Vista</os>
</query>
</iq>
java.lang.NullPointerException
        at java.util.concurrent.ConcurrentHashMap.remove(ConcurrentHashMap.java:922)
        at org.jivesoftware.openfire.IQRouter.handle(IQRouter.java:284)
        at org.jivesoftware.openfire.IQRouter.route(IQRouter.java:101)
        at org.jivesoftware.openfire.spi.PacketRouterImpl.route(PacketRouterImpl.java:68)
        at org.jivesoftware.openfire.net.StanzaHandler.processIQ(StanzaHandler.java:311)
        at org.jivesoftware.openfire.net.ClientStanzaHandler.processIQ(ClientStanzaHandler.java:79)
...

Obviously for some reason the resulting IQ packet has no packet-ID. That’s why we get an NullPointerException, but question is: why?

All errors have in common, that the other user, that one that has requested the IQ packet seems to use Miranda. That user that caused the second error I posted here is using an very old version of Miranda: 0.5.1. I assume that this old version does not send an packet-ID for the request, so the target user gets kicked from the server. With Miranda 0.7.8 I can not confirm that problem.

I will do a bit more investigation now…

I have this problem with Pidgin too. It seems that there went something wrong with the SSL encryption. When I set the old SSL method to Not Available it works for our setup, with and wihtout TLS method and of course with Pidgin

greetings

Ok, it’s this old Miranda, I can reproduce it now.

Test Environment 1

testuser1 uses Miranda 0.5.1 and is online. testuser2 uses Psi 0.12 and is offline. Both users have mutual subscription. Then testuser2 comes online. After connecting testuser2 gets directly kicked from the server. testuser1 is not harmed. This is the XML log of testuser2:

...
<iq from="testuser1@jabber.******.de/Miranda" type="get" to="testuser2@jabber.******.de/sempron2800" >
<query xmlns="jabber:iq:version"/>
</iq> <iq type="result" to="testuser1@jabber.********.de/Miranda" >
<query xmlns="jabber:iq:version">
<name>Psi</name>
<version>0.12</version>
<os>Fedora release 9 (Sulphur)</os>
</query>
</iq ...

As you see there is no packetID in both packets. This does conflict with RFC 3920, Page 51 (“The ‘id’ attribute is REQUIRED for IQ stanzas.”), so kicking users is reasonable. But, the server should kick the user who has caused this, not all others…definitely a bug within Openfire 3.6.0a, too.

Test Environment 2

Same as above, but with Miranda 0.7.8 for testuser1 instead. I found nothing unusual.

it’s not the old ssl method, i lay wrong with that.

I wrote an simple plugin as work around for this bug. This seems to work, but this is not XMPP conform, because Openfire does send an invaild reply packet itself, which is also dropped. I’m currently thinking about an workaround for this workaround

/** * GNU Public License (GPL). * * This software is published under the terms of the GNU Public License (GPL), * a copy of which is included in this distribution. */ package org.jivesoftware.openfire.plugin; import org.jivesoftware.openfire.container.Plugin; import org.jivesoftware.openfire.container.PluginManager; import org.jivesoftware.openfire.interceptor.PacketInterceptor;
import org.jivesoftware.openfire.interceptor.PacketRejectedException;
import org.jivesoftware.openfire.interceptor.InterceptorManager;
import org.jivesoftware.openfire.session.Session;
import org.jivesoftware.util.Log; import org.xmpp.packet.*; import java.io.File; public class Dropper implements Plugin, PacketInterceptor {     private InterceptorManager interceptorManager;     public Dropper() {
        interceptorManager = InterceptorManager.getInstance();     }     public void initializePlugin(PluginManager manager, File pluginDirectory) {         interceptorManager.addInterceptor(this);
    }             public void destroyPlugin() {         interceptorManager.removeInterceptor(this);     }     public void interceptPacket(Packet packet, Session session, boolean incoming, boolean processed)
            throws PacketRejectedException {
        if (processed) { return; }
        if (!(packet instanceof IQ)) { return; }         IQ iq = (IQ)packet;         if (iq.getID() == null) {
            Log.error("\nfound illegal IQ packet, packet was dropped:" + iq.toString());
            throw new PacketRejectedException("found illegal IQ packet");
        }                    } }

Ok, here it is:

Dropper Readme

This simple plugin drops IQ packets which have no ‘id’ attribute. According to RFC 3920 (Page 51) an ‘id’ attribute is required for IQ stanzas. Openfire 3.6.0a has an bug associated with this fact, which causes client disconnects. This problem is discussed here.

If the packet is not of type ‘error’, this plugin does also send an message to fromJID. You can change this message using plugin.dropper.message. You can change sender JID using plugin.dropper.jid. When changing any of these system properties, the plugin needs a restart.

Be aware that this plugin produces non-XMPP behavior! When droping IQ packets, XMPP requires an error packet send back. This packet is also dropped, because it does also not contain an valid ‘id’ attribute. Maybe there is an better way, but the best would surely be fixing the bug in Openfire directly.

**Be also aware that I have tested this not much! **However, it does run on my production system.

Message was edited by: Coolcat
dropper.jar (10869 Bytes)
dropper-0.3-src.tar.gz (9436 Bytes)

Ok, even newer Miranda versions seem to have this bug, just at another place. This is from Miranda 0.7.10.

<iq type="set" from="*****@jabber.rwth-aachen.de/Miranda">
  <query xmlns="jabber:iq:roster">
    <item jid="*********@jabber.rwth-aachen.de" subscription="none"/>
  </query>
</iq>

Also Trillian 3.1.7.0 has some problems when setting vCard:

<iq type="set" from="*****@jabber.rwth-aachen.de/meh">
  <vCard xmlns="vcard-temp">
    ...
  </vCard>
</iq>

A PacketInterceptor should be able to modify packets. Would it be wise just to add an random ‘id’ attribute and let the packet flow? Clients that don’t care about an ‘id’ attribute should simply ignore it, if there is suddenly one, right?

ok, seems to work…

Dropper Readme

This simple plugin tries to repair IQ packets which have no ‘id’ attribute. According to RFC 3920 (Page 51) an ‘id’ attribute is required for IQ stanzas. Openfire 3.6.0a has an bug associated with this fact, which causes client disconnects. This problem is discussed here.

If an packet has no ‘id’ attribute this plugin does modify the packet by simply adding an 12-digit random ‘id’.

Be aware that I have tested this not much!
dropper.jar (10231 Bytes)
dropper-0.4-src.tar.gz (8966 Bytes)

http://www.igniterealtime.org/issues/browse/JM-1465

When this appens to you, they appear as connected on Presence in Session List but when you check their status on their user properties they appear as offline or are they simply disconnected?

I’m having the first problem, and I believe it’s because of this.

Edit:

If this was my problem, your plugin didn’t solve it. (And I’m sorry for the offtopic but) does anyone knows were to download openfire 3.5.8 (rpm)?

Edit2:

Sorry, 3.5.2 and just found it. Thanks anyway.

Message was edited by: JR

When this appens to you, they appear as connected on Presence in
Session List but when you check their status on their user properties
they appear as offline or are they simply disconnected?
They are online for some milliseconds, until they answer that jabber:iq:version request. Then the server closes their connection.

In here they remain offline on the server, and the client “thinks” that they’re online.

I’ve notice something strange: I tried to send a message to all users in Sesssions>Tools and everyone received it: even the ones who were offline due to this problem.