Project

General

Profile

fail to message through tsung

kellogs .
Added over 4 years ago

Hi,

I keep getting

2014-06-16 23:09:51.840 [presence Queue Worker 6]  Presence.process()         INFO:     Can not access user Roster, user session is not authorized yet: from=sess-man@server1.domain.our, to=sess-man@server1.domain.our, DATA=<presence xmlns="jabber:client" from="+391344@domain.our/tsung" to="+391365@domain.our" type="unavailable" id="2832"/>, SIZE=132, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=unavailable

while tsunging our cluster installation. Our tigase is based on:

commit 48635d0a30a0a28e062b8da33a3d6f8453418866

Author: Wojciech Kapcia wojciech.kapcia@tigase.org

Date: Wed Feb 12 17:28:44 2014 +0100

tigase-server-5.2.0 release

tsung xml file:

http://pastebin.com/nc95vJUD

clusters init.properties:

http://pastebin.com/rXG98HVE

Tried even with:

-msgoffline: same result

~~msgoffline, -message, +amp: almost same result; besides the previous INFO message, also got another one ~~

2014-06-17 01:06:52.028 [amp Queue Worker 10] MessageAmp.process() INFO: Something wrong, DB problem, cannot load offline messages. tigase.db.UserNotFoundException: User: +3912455@domain.our/tsung was not found in database.

P.S. Just tried the same xml file against just one server (cluster mode off), same results. The server was not loaded at all -

top - 01:27:37 up 140 days,  7:23,  1 user,  load average: 0.53, 0.36, 1.84

P.P.S With cluster mode still turned off, tried the almost same xml - just lowered user rate from 50 to 5 u/s. Same deal.

Previous tests (1-2 years ago, older tigase) did not behave like that.

Thanks for any hints!


Replies (9)

Added by kellogs . over 4 years ago

Just tried again with the low 5 users/second setting and

tigase-server-5.2.0-b3447.jar 02/13/2014 07:20 pm 25.6 MB 19491 a1f75923079a1ac5c975656842e3bec7

version. Cluster mode on. Same deal.

And then with

tigase-server-5.2.1-b3461-dist.tar.gz 04/07/2014 09:36 pm 13.4 MB 296 6fe919655697ac6e966b8239dfb8426d

  • only kept the tigase-server.jar from that archive, same deal again.

So, the problem must lie not within the tigase.server.jar package, but somewhere else. Maybe in the configuration ?

Avatar?id=6023&size=32x32

Added by Artur Hefczyc TigaseTeam over 4 years ago

The offending presence stanza is of unavailable type. In your case it is generated by the server when user disconnects. However, to be honest, I do not see why could happen from the code. The only thing which comes to my mind is that your custom UserRepository implementation throws the NotAuthorizedException while the Presence plugin attempts to process the presence stanza and retrieve user's roster for that.

Have you tried removing the option:

sess-man/plugins-conf/skip-offline=true

This is quite experimental feature and it may affect results but I do not think this is the problem.

Added by kellogs . over 4 years ago

Hi,

thank you. It was not the

sess-man/plugins-conf/skip-offline=true

setting, and I was wrong about the two other versions misbehaving. Tried again with 5.2.1. and it went fine. The previous time I left old custom tigase-server.jar inside jars/ directory instead of removing it so i was still running the old one.

That means the problem is with our customized tigase-server. However, the

--user-db = tigase.db.jdbc.XGateRepository

class does not throw any NotAuthorizedException

sess-man/plugins-conf/dynamic-roster-classes=tigase.xmpp.impl.XGateRoster

class instead does throw the NotAuthorizedException, but it could not do otherwise (due to it implementing the tigase.xmpp.impl.roster.DynamicRosterIfc interface).

So, my question now is - how to further debug this ? Shouldn't the Presence class have logged any such exceptions getting thrown ? Right now all I have is

  • that it just happens on users closing their sessions

  • and not in very low number of users (it definitely happens at 2000, it may or may not happen at 200 simulated users, never for 20 users).

  • And not in very low user rate: no issue @ 5 u/s as opposed to 50 u/s over the same 2000 users.

For 2k users I only get the error in first post. Tried with 20k users and new errors popped up (both cases ran @ 50 u/s):

tons of:

2014-06-19 06:37:44.990 [presence Queue Worker 9]  Presence.process()         INFO:     Can not access user Roster, user session is not authorized yet: from=sess-man@server1.domain.our, to=sess-man@server1.domain.our, DATA=<presence id="90052" xmlns="jabber:client" type="unavailable" to="+3911259@domain.our" from="+3911234@domain.our/tsung"/>, SIZE=135, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=unavailable

also quite a few:

2014-06-19 06:37:52.254 [in_10-sess-man]   SessionManager.getXMPPResourceConnection()  INFO: Message without TO attribute set, don't know what to do wih this: from=c2s@server1.domain.our/192.168.101.25_443_192.168.101.32_62780, to=sess-man@server1.domain.our, DATA=<presence id="97333" xmlns="jabber:client"/>, SIZE=44, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null

and the occasional:

2014-06-19 06:37:50.332 [Thread-1529]      SessionManager$StaleConnectionCloser.closeConnections()  INFO: Trying to find and remove stale XMPPResourceConnections
2014-06-19 06:37:46.280 [in_72-sess-man]   SessionManager.processCommand()    INFO:     Stream close for the user session which does not exist: from=c2s@server1.domain.our/192.168.101.25_443_192.168.101.34_59476, to=sess-man@server1.domain.our, DATA=<iq from="+3911136@domain.our" type="set" id="3a947559-b86d-4213-b5a1-7120917521ec" to="sess-man@server1.domain.our"><command node="STREAM_CLOSED_UPDATE" xmlns="http://jabber.org/protocol/commands"/></iq>, SIZE=212, XMLNS=null, PRIORITY=SYSTEM, PERMISSION=NONE, TYPE=set
2014-06-19 06:32:20.295 [Thread-1518]      SessionManager$StaleConnectionCloser.closeConnections()  WARNING: Found stale XMPPResourceConnection: user_jid=+3911559@domain.our/tsung, packets=2, connectioId=c2s@server1.domain.our/192.168.101.25_443_192.168.101.33_43874, domain=domain.our, authState=AUTHORIZED, isAnon=false, isTmp=false, removing...
2014-06-19 06:37:46.235 [in_7-message-router]  MessageRouter.processPacket()  WARNING:  Packet with TO attribute set to NULL: from=sess-man@server1.domain.our, to=null, DATA=<message id="94418" type="error" xmlns="jabber:client" from="+3911030@domain.our"><body>qxvmvtglimieyhemzlxcqxvmvtglimieyhemzlxcqxvmvtglimieyhemzlxcqxvmvtglimieyhemzlxcqxvmvtglimieyhemzlxc</body><error type="cancel" code="404"><item-not-found xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/><text xmlns="urn:ietf:params:xml:ns:xmpp-stanzas" xml:lang="en">The user connection is no longer active.</text></error></message>, SIZE=424, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=error
2014-06-19 06:37:44.759 [message Queue Worker 13]  Message.process()          WARNING:  NotAuthorizedException for packet: from=sess-man@server1.domain.our, to=sess-man@server1.domain.our, DATA=<message id="94629" type="error" xmlns="jabber:client" to="+3911208@domain.our/tsung" from="+3911017@domain.our"><body>qxvmvtglimieyhemzlxcqxvmvtglimieyhemzlxcqxvmvtglimieyhemzlxcqxvmvtglimieyhemzlxcqxvmvtglimieyhemzlxc</body><error type="cancel" code="404"><item-not-found xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/><text xmlns="urn:ietf:params:xml:ns:xmpp-stanzas" xml:lang="en">The user connection is no longer active.</text></error></message>, SIZE=462, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=error
2014-06-19 06:37:44.881 [message Queue Worker 9]  Message.process()           WARNING:  NotAuthorizedException for packet: from=sess-man@server1.domain.our, to=sess-man@server1.domain.our, DATA=<message id="94309" type="chat" xmlns="jabber:client" to="+3911017@domain.our" from="+3911133@domain.our/tsung"><body>qxvmvtglimieyhemzlxcqxvmvtglimieyhemzlxcqxvmvtglimieyhemzlxcqxvmvtglimieyhemzlxcqxvmvtglimieyhemzlxc</body></message>, SIZE=249, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=chat
2014-06-19 06:37:44.085 [message Queue Worker 9]  SessionManager$ProcessorWorkerThread.process()  INFO: Already error packet, ignoring: from=c2s@server1.domain.our/192.168.101.25_443_192.168.101.33_20169, to=sess-man@server1.domain.our, DATA=<message id="93918" type="error" xmlns="jabber:client" to="+3911025@domain.our/tsung" from="+391775@domain.our"><body>CData size: 100</body><error type="cancel" code="404"><item-not-found xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/><text xmlns="urn:ietf:params:xml:ns:xmpp-stanzas" xml:lang="en">CData size: 40</text></error></message>, SIZE=461, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=error
2014-06-19 06:37:39.737 [pool-6-thread-1]  SessionManager$AuthenticationTimer.run()  INFO: Authentication timeout expired, closing connection: c2s@server1.domain.our/192.168.101.25_443_192.168.101.32_36247
2014-06-19 06:37:39.751 [pool-11-thread-17]  ClientConnectionManager.processSocketData()  INFO: Hm, receiver is not set yet (misconfiguration error)..., ignoring: from=c2s@server1.domain.our/192.168.101.25_443_192.168.101.32_4863, to=null, DATA=<iq id="94855" type="set" xmlns="jabber:client"><query xmlns="jabber:iq:auth"><username>CData size: 7</username><resource>CData size: 5</resource><password>CData size: 7</password></query></iq>, SIZE=173, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=set, connection: c2s@server1.domain.our/192.168.101.25_443_192.168.101.32_4863, type: accept, Socket: c2s@server1.domain.our/192.168.101.25_443_192.168.101.32_4863 Socket[addr=/192.168.101.32,port=4863,localport=443], jid: null

Thank you again!

P.S Hmm,if

sess-man/plugins-conf/dynamic-roster-classes=tigase.xmpp.impl.XGateRoster

gets commented away, then all runs fine. But, this means no rosters are involved whatsoever...

Well, almost all, just getting standard

2014-06-19 08:17:51.435 [pool-6-thread-1]  SessionManager$AuthenticationTimer.run()  INFO: Authentication timeout expired, closing connection: c2s@server225.xgate.com/192.168.101.25_443_192.168.101.31_30418
2014-06-19 08:17:51.445 [pool-11-thread-9]  ClientConnectionManager.processSocketData()  INFO: Hm, receiver is not set yet (misconfiguration error)..., ignoring: from=c2s@server225.xgate.com/192.168.101.25_443_192.168.101.31_14743, to=null, DATA=<iq id="36390" type="get" xmlns="jabber:client"><query xmlns="jabber:iq:auth"><username>CData size: 7</username></query></iq>, SIZE=119, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=get, connection: c2s@server225.xgate.com/192.168.101.25_443_192.168.101.31_14743, type: accept, Socket: c2s@server225.xgate.com/192.168.101.25_443_192.168.101.31_14743 Socket[addr=/192.168.101.31,port=14743,localport=443], jid: null
2014-06-19 08:18:00.138 [Thread-1495]      SessionManager$StaleConnectionCloser.closeConnections()  INFO: Trying to find and remove stale XMPPResourceConnections

Added by Wojciech Kapcia TigaseTeam over 4 years ago

Could you:

  • run the load test with --debug=xmpp.impl to get the stacktrace of the stacktrace from the Presence plugin;

  • share any other stacktraces if present;

  • share code of your dynamic roster implementation?

Added by kellogs . over 4 years ago

Hi,

I have added a few lines where that NotAuthorizedException was getting caught in the Presence.class and this is how it looks:

2014-06-20 01:21:28.035 [presence Queue Worker 2]  Presence.process()         INFO:     Can not access user Roster, user session is not authorized yet: from=sess-man@server1.domain.our, to=sess-man@server1.domain.our, DATA=<presence xmlns="jabber:client" to="+3911230@domain.our" type="unavailable" from="+3911219@domain.our/tsung" id="6741"/>, SIZE=134, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=unavailable
2014-06-20 01:21:28.036 [presence Queue Worker 2]  Presence.process()         WARNING:  Caught: tigase.xmpp.NotAuthorizedException: Session has not been yet authorised.

tigase.xmpp.NotAuthorizedException: Session has not been yet authorised.
        at tigase.xmpp.XMPPResourceConnection.isUserId(XMPPResourceConnection.java:900)
        at tigase.xmpp.impl.roster.RosterAbstract.getPresenceType(RosterAbstract.java:971)
        at tigase.xmpp.impl.Presence.process(Presence.java:350)
        at tigase.server.xmppsession.SessionManager$ProcessorWorkerThread.process(SessionManager.java:2714)
        at tigase.util.WorkerThread.run(WorkerThread.java:143)

Can't share the XGateRoster plugin code though. But that is a start from where to dig up the issue. I'll be back if need be.

Thank you!

Added by Wojciech Kapcia TigaseTeam over 4 years ago

One more thing - could you also collect server statistics from the load run, especially those related to processing time for plugins and share those?

(I also assume that sharing XGateRoster privately is not possible?)

Added by kellogs . over 4 years ago

Helo,

fixed the batch of error messages by modifying Presence.process(...):

turned:

        @if ( !session.isAuthorized() ){

            if ( log.isLoggable( Level.FINE ) ){

                log.log( Level.FINE, "Session is not authorized, ignoring packet: {0}", packet );

            }

            return;

        }

    // Synchronization to avoid conflict with login/logout events

    // processed in the SessionManager asynchronously

    synchronized ( session ) {@

into:

    @// Synchronization to avoid conflict with login/logout events

    // processed in the SessionManager asynchronously

    synchronized ( session ) {

        if ( !session.isAuthorized() ){

            if ( log.isLoggable( Level.FINE ) ){

                log.log( Level.FINE, "Session is not authorized, ignoring packet: {0}", packet );

            }

            return;

        }@

Seemed like a trivial fix. Hope I didn't break anything.

Added by kellogs . over 4 years ago

I mean fixed them all messages besides the usual

2014-06-19 08:17:51.435 [pool-6-thread-1]  SessionManager$AuthenticationTimer.run()  INFO: Authentication timeout expired, closing connection: c2s@server225.xgate.com/192.168.101.25_443_192.168.101.31_30418
2014-06-19 08:17:51.445 [pool-11-thread-9]  ClientConnectionManager.processSocketData()  INFO: Hm, receiver is not set yet (misconfiguration error)..., ignoring: from=c2s@server225.xgate.com/192.168.101.25_443_192.168.101.31_14743, to=null, DATA=<iq id="36390" type="get" xmlns="jabber:client"><query xmlns="jabber:iq:auth"><username>CData size: 7</username></query></iq>, SIZE=119, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=get, connection: c2s@server225.xgate.com/192.168.101.25_443_192.168.101.31_14743, type: accept, Socket: c2s@server225.xgate.com/192.168.101.25_443_192.168.101.31_14743 Socket[addr=/192.168.101.31,port=14743,localport=443], jid: null
2014-06-19 08:18:00.138 [Thread-1495]      SessionManager$StaleConnectionCloser.closeConnections()  INFO: Trying to find and remove stale XMPPResourceConnections

Added by kellogs . over 4 years ago

I now tend to get

2014-06-23 15:34:25.240 [jabber:iq:auth Queue Worker 1]  XMPPSession.addResourceConnection()  INFO: Exception during closing old connection, ignoring.
tigase.xmpp.NotAuthorizedException: Session has not been yet authorised.
        at tigase.xmpp.XMPPResourceConnection.getBareJID(XMPPResourceConnection.java:565)
        at tigase.xmpp.RepositoryAccess.logout(RepositoryAccess.java:378)
        at tigase.xmpp.XMPPResourceConnection.logout(XMPPResourceConnection.java:307)
        at tigase.xmpp.XMPPSession.addResourceConnection(XMPPSession.java:130)
        at tigase.xmpp.XMPPResourceConnection.setResource(XMPPResourceConnection.java:1018)
        at tigase.xmpp.impl.JabberIqAuth.process(JabberIqAuth.java:299)
        at tigase.server.xmppsession.SessionManager$ProcessorWorkerThread.process(SessionManager.java:2714)

whenrelaunching a tsung testing session after abruptly breaking another tsung sessions but I guess it is ok.

    (1-9/9)