Trouble logging onto server

Scott_Brissenden · February 8, 2008, 5:03pm

We have been using Exodus as the client to connect to Openfire for a few weeks and haven’t had any issues. We recently switched to spark and now when we get a few users connected we are having problems with others connecting. They receive an “invalid username or password” error if they wait a little while they can eventually log in. The admin console shows them authenticated but not connected. At our high point we have 260 users connected. Java vm memory hovers around 50% usage (max allowed is 256mb), the server itself has 512mb (i’m going to up to 1gb to see if it helps). Any ideas whats happening? Do we need to up the Java vm memory? I’m at a loss

This is kind of urget BTW any help is GREATLY appreciated.

Gaston_Dombiak · February 8, 2008, 6:14pm

Hey Scott,

Do you see any error in the log files of the server? While in the login window in Spark you can click on Advanced and check on the XML console debugger. Try logging in again and then paste here the sent and received raw XML that you see in the console debugger.

Thanks,

– Gato

Scott_Brissenden · February 8, 2008, 6:25pm

Sent:

<stream:stream to=“server name” xmlns=“jabber:client” xmlns:stream=“http://etherx.jabber.org/streams” version=“1.0”>

<auth mechanism=“PLAIN” xmlns=“urn:ietf:params:xml:ns:xmpp-sasl”>AHNicmlzc2VuAGJyaVMzNTE2</auth&g t;

<stream:stream to=“server name” xmlns=“jabber:client” xmlns:stream=“http://etherx.jabber.org/streams” version=“1.0”>

<iq id=“xt49v-1” type=“set”><bind xmlns=“urn:ietf:params:xml:ns:xmpp-bind”><resource>spark</resource& gt;</bind></iq>

Received:

<?xml version=‘1.0’ encoding=‘UTF-8’?><stream:stream xmlns:stream=“http://etherx.jabber.org/streams” xmlns=“jabber:client” from=“server name” id=“f56322df” xml:lang=“en” version=“1.0”>

<stream:features><mechanisms xmlns=“urn:ietf:params:xml:ns:xmpp-sasl”><mechanism>JIVE-SHAREDSECRET& lt;/mechanism><mechanism>PLAIN</mechanism><mechanism>ANONYM OUS</mechanism></mechanisms><auth xmlns=“http://jabber.org/features/iq-auth”/></stream:features>

<?xml version=‘1.0’ encoding=‘UTF-8’?><stream:stream xmlns:stream=“http://etherx.jabber.org/streams” xmlns=“jabber:client” from=“server name” id=“f56322df” xml:lang=“en” version=“1.0”><stream:features><bind xmlns=“urn:ietf:params:xml:ns:xmpp-bind”/><session xmlns=“urn:ietf:params:xml:ns:xmpp-session”/></stream:features>

<iq type=“result” id=“xt49v-1” to=“server name/f56322df”><bind xmlns=“urn:ietf:params:xml:ns:xmpp-bind”><jid>sbrissen@server name/spark</jid></bind></iq>

where it shows server name it shows the actual name of the server.

Gaston_Dombiak · February 8, 2008, 6:44pm

Hey Scott,

The exchanged XML looks fine. The user was able to authenticate and bind a resource. I’m wondering if the network is slow and Spark is timing out. In the advanced window could you try increasing the Response Timeout to a higher value? Also do you see any error in the log files?

Thanks,

– Gato

Scott_Brissenden · February 8, 2008, 7:04pm

I upped the timeout to 30 and i seem to be able to connect on a regular basis but it is slow populating the list.

Heres an error from the server:

org.jivesoftware.openfire.nio.ConnectionHandler.messageReceived(ConnectionHandle r.java:134) Closing connection due to error while proces

sing message: <auth mechanism=“PLAIN” xmlns=“urn:ietf:params:xml:ns:xmpp-sasl”>AAA=</auth>

java.util.NoSuchElementException

I’m guessing you are right with Spark timing out. Would upping the ram and Java mem be of any help?

Gaston_Dombiak · February 8, 2008, 7:11pm

Hey Scott,

Hard to tell from here what is slowing down the connections. Try increasing the max heap size on the server and see if that helps.

Regards,

– Gato

Scott_Brissenden · February 11, 2008, 2:31pm

I upped the ram to 1gb in the server and upped the heap size to 512mb. Still getting the problems. I’m guessing that running Spark from a shared location is probably the cause. I was trying to avoid installing it company wide so that we have more control over it. Any idea if using webstart is an option for spark?

Scott_Brissenden · February 11, 2008, 2:46pm

Also forgot to mention that Openfire is a Xen vm but the network IO, load, mem usage is low on both the vm and its host.

Scott_Brissenden · February 11, 2008, 2:50pm

A couple more errors I’m seeing in the logs:

2008.02.11 09:35:39 org.jivesoftware.openfire.handler.IQAuthHandler.handleIQ(IQAuthHandler.java:93) Error during authentication. Session not found in [ff6cf

eaa, aae4970f, 8e665935, 8b53286f, 1ea6d047, d8b3bd95, 849aa476, 2beef93b, 85a7852a, 54ad0e15, d4be494d, bc5a37b2, 8253bb06, b1a91b5a, e6188bf6, 1882823, d872

7518, f90ade73, 90de02fb, f1562967, d91defb, 2281413a, 98f3b92f, 8c1f10af, a7a6ac25, 71abddc2, 119573a0, 13a575c5, 3c572cc9, 174fca01, 27c1e3de, ad0d1458, d2e

a6ea3, c5450b91, c070981, cbc8f037, e565746c, 95a13ec0, 677f2656, fb719509, c894470d, 343d4023, 856e25ce, b921ea7b, ffaad659, baa3dc0f] for key server name/7e87b754

2008.02.11 09:36:08 org.jivesoftware.openfire.PresenceRouter.handle(PresenceRouter.java:193) Could not route packet

java.lang.NullPointerException

I’m in a bind right now

Scott_Brissenden · February 11, 2008, 6:45pm

So I migrated the virtual machine to a dual cpu 3.0ghz server with 2gb of ram as well as upped the java mem to 1gb and things seem to be good so far (knock on wood). Oddly enough the java mem is WAY down, maybe java was having a hard time keeping up before?

Scott_Brissenden · February 12, 2008, 6:25pm

Alot of the “Invalid username/password” issues are gone now but we are still experiencing a few throughout the day. It only happens when he have 200+ users logged. Other times, logging in is slow but once the group list is populated things run pretty good. I noticed that Java runs at 100+% cpu load, is this normal? Would adding a connection manager make a difference? I was under the impression that I wouldn’t one but maybe thats not true.

Gaston_Dombiak · February 12, 2008, 6:55pm

200 users and CPU at 100% is not normal. I would recommend doing a few thread dumps of the JVM (kill -3 [processid]) and also verify the logs for errors.

Regards,

– Gato

Scott_Brissenden · February 12, 2008, 7:35pm

load average: 1.47, 1.68, 1.60

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND

18616 daemon 23 0 1306m 421m 8392 S 116 21.0 385:18.96 java

This is the output of top, Its a dual cpu so they are not pegged but look at the java cpu%(in bold). its consistently up there.

Heres something in the error log:

2008.02.12 10:45:10 ~~org.jivesoftware.openfire.nio.ConnectionHandler.messageReceived(ConnectionHandle r.java:134)~~ Closing connection due to error while proessing message: <stream:error><system-shutdown xmlns=‘urn:ietf:params:xml:ns:xmpp-streams’/></stream:error>

org.xmlpull.v1.XmlPullParserException: could not determine namespace bound to element prefix stream (position: START_DOCUMENT seen <stream:error>… @1:14)

2008.02.12 11:26:30 ~~org.jivesoftware.openfire.handler.IQHandler.process(IQHandler.java:68)~~ Internal server error

java.lang.NullPointerException: replacement

Is there something specific in the thread dump I should be looking for?

Gaston_Dombiak · February 12, 2008, 8:04pm

Hey Scott,

Can you post the entire stack trace of those exceptions? How frequent is the second exception? Frequent logging of errors could produce what you are seeing.

Thanks,

– Gato

Scott_Brissenden · February 12, 2008, 8:22pm

2008.02.12 10:45:10 org.jivesoftware.openfire.nio.ConnectionHandler.messageReceived(ConnectionHandle r.java:134) Closing connection due to error while pro

cessing message: <stream:error><system-shutdown xmlns=‘urn:ietf:params:xml:ns:xmpp-streams’/></stream:error>

org.xmlpull.v1.XmlPullParserException: could not determine namespace bound to element prefix stream (position: START_DOCUMENT seen <stream:error>… @1:14)

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

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

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

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

at org.dom4j.io.XMPPPacketReader.parseDocument(XMPPPacketReader.java:317)

at org.dom4j.io.XMPPPacketReader.read(XMPPPacketReader.java:154)

at org.jivesoftware.openfire.net.StanzaHandler.process(StanzaHandler.java:132)

at org.jivesoftware.openfire.nio.ConnectionHandler.messageReceived(ConnectionHandl er.java:132)

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.filter.codec.support.SimpleProtocolDecoderOutput.flush(SimplePr otocolDecoderOutput.java:58)

at org.apache.mina.filter.codec.ProtocolCodecFilter.messageReceived(ProtocolCodecF ilter.java:173)

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(Unknown Source)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)

at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:51)

at java.lang.Thread.run(Unknown Source)

2008.02.12 11:26:30 org.jivesoftware.openfire.handler.IQHandler.process(IQHandler.java:68) Internal server error

java.lang.NullPointerException: replacement

at java.util.regex.Matcher.replaceFirst(Unknown Source)

at java.lang.String.replaceFirst(Unknown Source)

at org.jivesoftware.openfire.ldap.LdapVCardProvider$VCard.treeWalk(LdapVCardProvid er.java:520)

at org.jivesoftware.openfire.ldap.LdapVCardProvider$VCard.treeWalk(LdapVCardProvid er.java:524)

at org.jivesoftware.openfire.ldap.LdapVCardProvider$VCard.getVCard(LdapVCardProvid er.java:501)

at org.jivesoftware.openfire.ldap.LdapVCardProvider.loadVCard(LdapVCardProvider.ja va:215)

at org.jivesoftware.openfire.vcard.VCardManager.getOrLoadVCard(VCardManager.java:2 04)

at org.jivesoftware.openfire.vcard.VCardManager.getVCard(VCardManager.java:197)

at org.jivesoftware.openfire.handler.IQvCardHandler.handleIQ(IQvCardHandler.java:1 07)

at org.jivesoftware.openfire.handler.IQHandler.process(IQHandler.java:48)

at org.jivesoftware.openfire.IQRouter.handle(IQRouter.java:348)

at org.jivesoftware.openfire.IQRouter.route(IQRouter.java:100)

at org.jivesoftware.openfire.spi.PacketRouterImpl.route(PacketRouterImpl.java:67)

at org.jivesoftware.openfire.net.StanzaHandler.processIQ(StanzaHandler.java:303)

at org.jivesoftware.openfire.net.ClientStanzaHandler.processIQ(ClientStanzaHandler .java:78)

at org.jivesoftware.openfire.net.StanzaHandler.process(StanzaHandler.java:268)

at org.jivesoftware.openfire.net.StanzaHandler.process(StanzaHandler.java:167)