Use of Thread.currentThread().hashCode in ConnectionHandler is non-unique

As an optimization, org/jivesoftware/openfire/nio/ConnectionHandler.java, makes a map of XMPPPacketReader instances, lazily creating a reader for each Thread.

There is a problem with this code, in that messageReceived uses Thread.currentThread().hashCode, which is not guaranteed to be unique, rather than something that would be unique, such as ThreadLocal, or Thread.currentThread() or Thread.currentThread().getId().

The result that we have seen, exacerbated by high loads, is that you can occasionally get XMLParser errors, which seem to have totally bogus error results, in relation to the stanza that was put to the parser, since two thread will be using the same parser.

Does not always happen, but when it does, it is hard to diagnose and trace it back to this problem.

You can get exceptions like:

15:14:01,426 [Old SSL executor thread - 19] ERROR org.jivesoftware.openfire.nio.ConnectionHandler - Closing connection for parser [580145283] due to error while processing message: Online5

                            <x xmlns='http://jabber.org/protocol/muc&#39;xmlns:wm='xxxx:mucom' />

                            <x xmlns='xxxx:mucprivacy'><list name='blocked'><item action='allow' order='2'>

                            <presence-out/><message/><iq/></item></list></x><x xmlns='vcard-temp:x:update' xmlns:wpu='xxxx:profile:update' ><photo>3fcf460c7ae958ff8a7a9af31641a62363eb63bd</photo><wpu:profile ver='1' >d2675456f1801efb9a3f47b1430c8e2f302e2cc7</wpu:profile></x><name xmlns='xxxx:temp' family='user333779' given='user333779' /></presence>; prev: <presence><status>Online</status><priority>5</priority><x xmlns='vcard-temp:x:update' xmlns:wpu='xxx:profile:update' ><photo>3fcf460c7ae958ff8a7a9af31641a62363eb63bd</photo><wpu:profile ver='1' >d2675456f1801efb9a3f47b1430c8e2f302e2cc7</wpu:profile></x></presence>

java.lang.StringIndexOutOfBoundsException: String index out of range: -120

           at java.lang.String.<init>(String.java:207)

            at org.xmlpull.mxp1.MXParser.parseAttribute(MXParser.java:2141)

            at org.xmlpull.mxp1.MXParser.parseStartTag(MXParser.java:1799)

            at org.xmlpull.mxp1.MXParser.parseProlog(MXParser.java:1479)

            at org.jivesoftware.openfire.net.MXParser.nextImpl(MXParser.java:341)

15:14:01,426 [Old SSL executor thread - 12] ERROR org.jivesoftware.openfire.nio.ConnectionHandler - Closing connection for parser [580145283] due to error while processing message: Online5

                            <x xmlns='http://jabber.org/protocol/muc&#39;xmlns:wm='xxxx:mucom' />

                            <x xmlns='xxxx:mucprivacy'><list name='blocked'><item action='allow' order='2'>

                            <presence-out/><message/><iq/></item></list></x><x xmlns='vcard-temp:x:update' xmlns:wpu='xxxx:profile:update' ><photo>3fcf460c7ae958ff8a7a9af31641a62363eb63bd</photo><wpu:profile ver='1' >d2675456f1801efb9a3f47b1430c8e2f302e2cc7</wpu:profile></x><name xmlns='xxxx:temp' family='user441121' given='user441121' /></presence>; prev: <presence><status>Online</status><priority>5</priority><x xmlns='vcard-temp:x:update' xmlns:wpu='xxxx:profile:update' ><photo>3fcf460c7ae958ff8a7a9af31641a62363eb63bd</photo><wpu:profile ver='1' >d2675456f1801efb9a3f47b1430c8e2f302e2cc7</wpu:profile></x></presence>

org.xmlpull.v1.XmlPullParserException: start tag unexpected character 3 (position: START_DOCUMENT @1:68)

            at org.xmlpull.mxp1.MXParser.parseStartTag(MXParser.java:1803)

            at org.jivesoftware.openfire.net.MXParser.nextImpl(MXParser.java:200)

            at org.xmlpull.mxp1.MXParser.nextToken(MXParser.java:1100)

Or the more esoteric:

00:22:44,750 [Old SSL executor thread - 13] ERROR org.jivesoftware.openfire.nio.ConnectionHandler - Closing connection due to error while processing message: <query xmlns='jabber:i

q:privacy’>

java.io.EOFException: no more data available - expected end tag to close start tag from line 1, parser stopped on END_TAG seen …xxxx.local/user507777’ type='un

available’/>… @1:89

    at org.xmlpull.mxp1.MXParser.fillBuf(MXParser.java:3014)

    at org.xmlpull.mxp1.MXParser.more(MXParser.java:3025)

    at org.jivesoftware.openfire.net.MXParser.more(MXParser.java:373)

or

03:33:54,260 [Old SSL executor thread - 13] ERROR org.jivesoftware.openfire.nio.ConnectionHandler - Closing connection due to error while processing message: <query xmlns='jabber:i

q:privacy’>

java.io.EOFException: no more data available - expected end tag to close start tag from line 1, parser stopped on END_TAG seen …<list name=‘blocked’/>… @1:97

    at org.xmlpull.mxp1.MXParser.fillBuf(MXParser.java:3014)

    at org.xmlpull.mxp1.MXParser.more(MXParser.java:3025)

    at org.jivesoftware.openfire.net.MXParser.more(MXParser.java:373)

Where the tags that are claimed to be missing are obviously there.

Tom

Good debugging, that must have been hard to find. Logged as OF-565.

Was this with version 3.7.1?

This was with a 3.7.1 based system. The key was when the lead developer extended error messages, printing the hash code of the parser instance. It showed up as the same for multiple Old SSL executor threads, and the scales dropped away.

I believe that the code has been in for some time though.