Project

General

Profile

SEVER internal error in tigase-console.log

Ehsan Mozaffari
Added almost 3 years ago

Hi,

We have an issue to use PubSub in tigase-server-7.0.3-b3830 (Using tigase-b3821 Mysql schema). The problem is that when we try to Retrieve Subscriptions in PubSub similar to the following stanza:

<iq type='get'
    from='francisco@denmark.lit/barracks'
    to='pubsub.shakespeare.lit'
    id='subscriptions1'>
  <pubsub xmlns='http://jabber.org/protocol/pubsub'>
    <subscriptions/>
  </pubsub>
</iq>

We get the following errors in PSI console:

<iq from="pubsub.shakespeare.lit" type="error" to="francisco@denmark.lit/barracks " id="subscriptions1">
<pubsub xmlns="http://jabber.org/protocol/pubsub">
<subscriptions/>
</pubsub>
<error type="wait" code="500">
<internal-server-error xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/>
</error>
</iq>

And at the same time, we receive the following SEVER errors in tigase-console.log:

tigase.pubsub.repository.RepositoryException: User affiliations reading error
        at tigase.pubsub.repository.PubSubDAOJDBC.getUserSubscriptions(PubSubDAOJDBC.java:625)
        at tigase.pubsub.repository.PubSubDAOPool.getUserSubscriptions(PubSubDAOPool.java:381)
        at tigase.pubsub.modules.RetrieveSubscriptionsModule.process(RetrieveSubscriptionsModule.java:112)
        at tigase.component2.modules.ModulesManager.process(ModulesManager.java:87)
        at tigase.component2.AbstractComponent.processStanzaPacket(AbstractComponent.java:221)
        at tigase.component2.AbstractComponent.processPacket(AbstractComponent.java:209)
        at tigase.pubsub.PubSubComponent.processPacket(PubSubComponent.java:599)
        at tigase.pubsub.cluster.PubSubComponentClustered.processPacket(SourceFile:129)
        at tigase.server.AbstractMessageReceiver$QueueListener.run(AbstractMessageReceiver.java:1424)
Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: No operations allowed after statement closed.
        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57)
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
        at java.lang.reflect.Constructor.newInstance(Constructor.java:526)
        at com.mysql.jdbc.Util.handleNewInstance(Util.java:406)
        at com.mysql.jdbc.Util.getInstance(Util.java:381)
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1012)
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:986)
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:981)
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:926)
        at com.mysql.jdbc.StatementImpl.checkClosed(StatementImpl.java:405)
        at com.mysql.jdbc.PreparedStatement.setString(PreparedStatement.java:4374)
        at tigase.pubsub.repository.PubSubDAOJDBC.getUserSubscriptions(PubSubDAOJDBC.java:613)
        ... 8 more
2016-04-13 10:22:00.710 [in_0-pubsub]      AbstractComponent.processStanzaPacket()  SEVERE: tigase.pubsub.repository.RepositoryException: User affiliations reading error when processing from=sess-man@shakespeare.lit , to=null, DATA=<iq xmlns="jabber:client" from="francisco@denmark.lit/barracks " to="pubsub.shakespeare.lit " type="get" id="subscriptions1">
<pubsub xmlns="http://jabber.org/protocol/pubsub">
  <subscriptions/></pubsub></iq>, SIZE=199, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=get
java.lang.RuntimeException: tigase.pubsub.repository.RepositoryException: User affiliations reading error
        at tigase.pubsub.modules.RetrieveSubscriptionsModule.process(RetrieveSubscriptionsModule.java:140)
        at tigase.component2.modules.ModulesManager.process(ModulesManager.java:87)
        at tigase.component2.AbstractComponent.processStanzaPacket(AbstractComponent.java:221)
        at tigase.component2.AbstractComponent.processPacket(AbstractComponent.java:209)
        at tigase.pubsub.PubSubComponent.processPacket(PubSubComponent.java:599)
        at tigase.pubsub.cluster.PubSubComponentClustered.processPacket(SourceFile:129)
        at tigase.server.AbstractMessageReceiver$QueueListener.run(AbstractMessageReceiver.java:1424)
Caused by: tigase.pubsub.repository.RepositoryException: User affiliations reading error
        at tigase.pubsub.repository.PubSubDAOJDBC.getUserSubscriptions(PubSubDAOJDBC.java:625)
        at tigase.pubsub.repository.PubSubDAOPool.getUserSubscriptions(PubSubDAOPool.java:381)
        at tigase.pubsub.modules.RetrieveSubscriptionsModule.process(RetrieveSubscriptionsModule.java:112)
        at tigase.component2.modules.ModulesManager.process(ModulesManager.java:87)
        at tigase.component2.AbstractComponent.processStanzaPacket(AbstractComponent.java:221)
        at tigase.component2.AbstractComponent.processPacket(AbstractComponent.java:209)
        at tigase.pubsub.PubSubComponent.processPacket(PubSubComponent.java:599)
        at tigase.pubsub.cluster.PubSubComponentClustered.processPacket(SourceFile:129)
        at tigase.server.AbstractMessageReceiver$QueueListener.run(AbstractMessageReceiver.java:1424)
Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: No operations allowed after statement closed.
        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57)
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
        at java.lang.reflect.Constructor.newInstance(Constructor.java:526)
        at com.mysql.jdbc.Util.handleNewInstance(Util.java:406)
        at com.mysql.jdbc.Util.getInstance(Util.java:381)
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1012)
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:986)
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:981)
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:926)
        at com.mysql.jdbc.StatementImpl.checkClosed(StatementImpl.java:405)
        at com.mysql.jdbc.PreparedStatement.setString(PreparedStatement.java:4374)
        at tigase.pubsub.repository.PubSubDAOJDBC.getUserSubscriptions(PubSubDAOJDBC.java:613)
        at tigase.pubsub.repository.PubSubDAOPool.getUserSubscriptions(PubSubDAOPool.java:381)
        at tigase.pubsub.modules.RetrieveSubscriptionsModule.process(RetrieveSubscriptionsModule.java:112)
        at tigase.component2.modules.ModulesManager.process(ModulesManager.java:87)
        at tigase.component2.AbstractComponent.processStanzaPacket(AbstractComponent.java:221)
        at tigase.component2.AbstractComponent.processPacket(AbstractComponent.java:209)
        at tigase.pubsub.PubSubComponent.processPacket(PubSubComponent.java:599)
        at tigase.pubsub.cluster.PubSubComponentClustered.processPacket(SourceFile:129)
        at tigase.server.AbstractMessageReceiver$QueueListener.run(AbstractMessageReceiver.java:1424)

Thank you beforehand for your time and consideration.


Replies (13)

(1)

Added by Wojciech Kapcia TigaseTeam almost 3 years ago

Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: No operations allowed after statement closed.
…
        at com.mysql.jdbc.PreparedStatement.setString(PreparedStatement.java:4374)
        at tigase.pubsub.repository.PubSubDAOJDBC.getUserSubscriptions(PubSubDAOJDBC.java:613)

Exception is thrown while trying to set parameters to PreparedStatement, which would indicate some problem with the database connectivity. Is this the only exception in the logs? Are you able to perform other operations on PubSub?

Added by Ehsan Mozaffari almost 3 years ago

Thank you for reply.

Actually, this is a test server with local database, to my understanding, the database connectivity should be OK.

This is the only exception error in logs. I have tried the most of other operations in PubSub and it works without any error, but when I try to get the Subscriptions and affiliations in Pubsub, I receive the exceptions.

(1)

Added by Wojciech Kapcia TigaseTeam almost 3 years ago

Does the problem persists aster a restart?

Added by Ehsan Mozaffari almost 3 years ago

After restarting the server the error disappears, but it occurs after a while and the errors show up again randomly (sometimes after few hours, sometimes after few days).

(1)

Added by Wojciech Kapcia TigaseTeam almost 3 years ago

Can you enable verbose debugging:

  • include following in your debug statement:
--debug=server,xmpp.impl,pubsub
  • add &profileSQL=true to your --user-db-uri=… string, e.g.:
--user-db-uri=jdbc:mysql://localhost:3306/tigasedb?user=tigase&password=tigase&autoCreateUser=true&profileSQL=true

And then share complete logs? (Please clear the logs before so we will only get current details)

(1)

Added by Ehsan Mozaffari almost 3 years ago

We added

--debug=server,xmpp.impl,pubsub
--user-db-uri=jdbc:mysql://localhost:3306/tigasedb?user=tigase&password=tigase&autoCreateUser=true&profileSQL=true

And then we are receiving the following errors:

Tigase.log.0:

2016-04-25 07:38:55.546 [pool-17-thread-3]  ClientConnectionManager.processSocketData()  FINEST: Processing socket data: from=null, to=null, DATA=<iq from="francisco@denmark.lit/barracks" to="pubsub.shakespeare.lit" type="get" id="subscriptions1">
<pubsub xmlns="http://jabber.org/protocol/pubsub">CData size: 3<subscriptions/></pubsub></iq>, SIZE=185, XMLNS=null, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=get from connection: c2s@shakespeare.lit/192.168.44.81_5222_192.168.36.151_5751
2016-04-25 07:38:55.546 [pool-17-thread-3]  ClientConnectionManager.processSocketData()  FINEST: XMLNS set for packet: from=null, to=null, DATA=<iq from="francisco@denmark.lit/barracks" to="pubsub.shakespeare.lit" type="get" id="subscriptions1" xmlns="jabber:client">
<pubsub xmlns="http://jabber.org/protocol/pubsub">CData size: 3<subscriptions/></pubsub></iq>, SIZE=207, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=get from connection: c2s@shakespeare.lit/192.168.44.81_5222_192.168.36.151_5751
2016-04-25 07:38:55.547 [in_3-message-router]  MessageRouter.processPacket()  FINEST:   Processing packet: from=c2s@shakespeare.lit/192.168.44.81_5222_192.168.36.151_5751, to=sess-man@shakespeare.lit, DATA=<iq id="subscriptions1" to="pubsub.shakespeare.lit" type="get" xmlns="jabber:client">
<pubsub xmlns="http://jabber.org/protocol/pubsub">
  <subscriptions/></pubsub></iq>, SIZE=165, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=get
2016-04-25 07:38:55.547 [in_3-message-router]  MessageRouter.getLocalComponent()  FINEST: Called for : pubsub.shakespeare.lit
2016-04-25 07:38:55.548 [in_3-message-router]  MessageRouter.getLocalComponent()  FINEST: No componentID matches (fast lookup against exact address): pubsub.shakespeare.lit, for map: [monitor@shakespeare.lit, ws2s@shakespeare.lit, pubsub@shakespeare.lit, stats@shakespeare.lit, message-archive@shakespeare.lit, basic-conf@shakespeare.lit, muc@shakespeare.lit, s2s@shakespeare.lit, sess-man@shakespeare.lit, vhost-man@shakespeare.lit, http@shakespeare.lit, ssend@shakespeare.lit, srecv@shakespeare.lit, c2s@shakespeare.lit, bosh@shakespeare.lit]; trying VHost lookup
2016-04-25 07:38:55.548 [in_3-message-router]  MessageRouter.getLocalComponent()  FINEST: No component name matches (VHost lookup against component name): pubsub.shakespeare.lit, for map: [ssend, c2s, basic-conf, s2s, bosh, vhost-man, sess-man, ws2s, message-router, message-archive, pubsub, stats, srecv, monitor, http, muc], for all VHosts: [shakespeare.lit, shakespeare.lit]; trying other forms of addressing
2016-04-25 07:38:55.548 [in_3-message-router]  MessageRouter.getLocalComponent()  FINEST: Component matched: pubsub.shakespeare.lit, for comp: [ssend, c2s, basic-conf, s2s, bosh, vhost-man, sess-man, ws2s, message-router, message-archive, pubsub, stats, srecv, monitor, http, muc], basename: shakespeare.lit
2016-04-25 07:38:55.548 [in_3-message-router]  MessageRouter.getLocalComponent()  FINEST: Called for : sess-man@shakespeare.lit
2016-04-25 07:38:55.549 [in_3-message-router]  MessageRouter.processPacket()  FINEST:   1. Packet will be processed by: sess-man@shakespeare.lit, from=c2s@shakespeare.lit/192.168.44.81_5222_192.168.36.151_5751, to=sess-man@shakespeare.lit, DATA=<iq id="subscriptions1" to="pubsub.shakespeare.lit" type="get" xmlns="jabber:client">
<pubsub xmlns="http://jabber.org/protocol/pubsub">
  <subscriptions/></pubsub></iq>, SIZE=165, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=get
2016-04-25 07:38:55.549 [in_7-sess-man]    SessionManager.processPacket()     FINEST:   Received packet: from=c2s@shakespeare.lit/192.168.44.81_5222_192.168.36.151_5751, to=sess-man@shakespeare.lit, DATA=<iq id="subscriptions1" to="pubsub.shakespeare.lit" type="get" xmlns="jabber:client">
<pubsub xmlns="http://jabber.org/protocol/pubsub">CData size: 3<subscriptions/></pubsub></iq>, SIZE=165, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=get
2016-04-25 07:38:55.549 [in_7-sess-man]    SessionManager.processPacket()     FINEST:   processing packet: from=c2s@shakespeare.lit/192.168.44.81_5222_192.168.36.151_5751, to=sess-man@shakespeare.lit, DATA=<iq id="subscriptions1" to="pubsub.shakespeare.lit" type="get" xmlns="jabber:client">
<pubsub xmlns="http://jabber.org/protocol/pubsub">CData size: 3<subscriptions/></pubsub></iq>, SIZE=165, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=get, connection: XMPPResourceConnection=[user_jid=francisco@denmark.lit/barracks, packets=48, connectioId=c2s@shakespeare.lit/192.168.44.81_5222_192.168.36.151_5751, domain=shakespeare.lit, authState=AUTHORIZED, isAnon=false, isTmp=false]
2016-04-25 07:38:55.549 [in_7-sess-man]    StartTLS.preProcess()              FINEST:   VHost: Domain: shakespeare.lit, enabled: true, anonym: false, register: true, maxusers: 0, tls: false, s2sSecret: 715dbc5e-07f9-42d1-b1dd-0522100d3135, domainFilter: ALL, domainFilterDomains: null, c2sPortsAllowed: null, saslAllowedMechanisms: null
2016-04-25 07:38:55.549 [in_7-sess-man]    BindResource.preProcess()          FINEST:   Setting correct from attribute: francisco@denmark.lit/barracks
2016-04-25 07:38:55.550 [in_7-sess-man]    SessionManager.processPacket()     FINEST:   Packet processed by: [default-handler]
2016-04-25 07:38:55.550 [default-handler Queue Worker 2]  SessionManager$DefaultHandlerProc.process()  FINEST: Executing default packet handler for: from=c2s@shakespeare.lit/192.168.44.81_5222_192.168.36.151_5751, to=sess-man@shakespeare.lit, DATA=<iq id="subscriptions1" to="pubsub.shakespeare.lit" type="get" xmlns="jabber:client" from="francisco@denmark.lit/barracks">
<pubsub xmlns="http://jabber.org/protocol/pubsub">
  <subscriptions/></pubsub></iq>, SIZE=207, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=get
2016-04-25 07:38:55.550 [default-handler Queue Worker 2]  PacketDefaultHandler.process()  FINEST: Processing packet: from=c2s@shakespeare.lit/192.168.44.81_5222_192.168.36.151_5751, to=sess-man@shakespeare.lit, DATA=<iq id="subscriptions1" to="pubsub.shakespeare.lit" type="get" xmlns="jabber:client" from="francisco@denmark.lit/barracks">
<pubsub xmlns="http://jabber.org/protocol/pubsub">CData size: 3<subscriptions/></pubsub></iq>, SIZE=207, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=get
2016-04-25 07:38:55.550 [default-handler Queue Worker 2]  JabberIqPrivacy.filter()  FINEST: Checking outbound packet: from=null, to=null, DATA=<iq id="subscriptions1" to="pubsub.shakespeare.lit" type="get" xmlns="jabber:client" from="francisco@denmark.lit/barracks">
<pubsub xmlns="http://jabber.org/protocol/pubsub">
  <subscriptions/></pubsub></iq>, SIZE=207, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=get
2016-04-25 07:38:55.551 [default-handler Queue Worker 2]  JabberIqPrivacy.allowed()  FINEST: Using privcy list: null
2016-04-25 07:38:55.551 [in_0-message-router]  MessageRouter.processPacket()  FINEST:   Processing packet: from=sess-man@shakespeare.lit, to=null, DATA=<iq id="subscriptions1" to="pubsub.shakespeare.lit" type="get" xmlns="jabber:client" from="francisco@denmark.lit/barracks">
<pubsub xmlns="http://jabber.org/protocol/pubsub">
  <subscriptions/></pubsub></iq>, SIZE=207, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=get
2016-04-25 07:38:55.551 [in_0-message-router]  MessageRouter.getLocalComponent()  FINEST: Called for : pubsub.shakespeare.lit
2016-04-25 07:38:55.551 [in_0-message-router]  MessageRouter.getLocalComponent()  FINEST: No componentID matches (fast lookup against exact address): pubsub.shakespeare.lit, for map: [monitor@shakespeare.lit, ws2s@shakespeare.lit, pubsub@shakespeare.lit, stats@shakespeare.lit, message-archive@shakespeare.lit, basic-conf@shakespeare.lit, muc@shakespeare.lit, s2s@shakespeare.lit, sess-man@shakespeare.lit, vhost-man@shakespeare.lit, http@shakespeare.lit, ssend@shakespeare.lit, srecv@shakespeare.lit, c2s@shakespeare.lit, bosh@shakespeare.lit]; trying VHost lookup
2016-04-25 07:38:55.552 [in_0-message-router]  MessageRouter.getLocalComponent()  FINEST: No component name matches (VHost lookup against component name): pubsub.shakespeare.lit, for map: [ssend, c2s, basic-conf, s2s, bosh, vhost-man, sess-man, ws2s, message-router, message-archive, pubsub, stats, srecv, monitor, http, muc], for all VHosts: [shakespeare.lit, shakespeare.lit]; trying other forms of addressing
2016-04-25 07:38:55.552 [in_0-message-router]  MessageRouter.getLocalComponent()  FINEST: Component matched: pubsub.shakespeare.lit, for comp: [ssend, c2s, basic-conf, s2s, bosh, vhost-man, sess-man, ws2s, message-router, message-archive, pubsub, stats, srecv, monitor, http, muc], basename: shakespeare.lit
2016-04-25 07:38:55.552 [in_0-message-router]  MessageRouter.getLocalComponent()  FINEST: Called for : pubsub.shakespeare.lit
2016-04-25 07:38:55.552 [in_0-message-router]  MessageRouter.getLocalComponent()  FINEST: No componentID matches (fast lookup against exact address): pubsub.shakespeare.lit, for map: [monitor@shakespeare.lit, ws2s@shakespeare.lit, pubsub@shakespeare.lit, stats@shakespeare.lit, message-archive@shakespeare.lit, basic-conf@shakespeare.lit, muc@shakespeare.lit, s2s@shakespeare.lit, sess-man@shakespeare.lit, vhost-man@shakespeare.lit, http@shakespeare.lit, ssend@shakespeare.lit, srecv@shakespeare.lit, c2s@shakespeare.lit, bosh@shakespeare.lit]; trying VHost lookup
2016-04-25 07:38:55.552 [in_0-message-router]  MessageRouter.getLocalComponent()  FINEST: No component name matches (VHost lookup against component name): pubsub.shakespeare.lit, for map: [ssend, c2s, basic-conf, s2s, bosh, vhost-man, sess-man, ws2s, message-router, message-archive, pubsub, stats, srecv, monitor, http, muc], for all VHosts: [shakespeare.lit, shakespeare.lit]; trying other forms of addressing
2016-04-25 07:38:55.553 [in_0-message-router]  MessageRouter.getLocalComponent()  FINEST: Component matched: pubsub.shakespeare.lit, for comp: [ssend, c2s, basic-conf, s2s, bosh, vhost-man, sess-man, ws2s, message-router, message-archive, pubsub, stats, srecv, monitor, http, muc], basename: shakespeare.lit
2016-04-25 07:38:55.553 [in_0-message-router]  MessageRouter.processPacket()  FINEST:   1. Packet will be processed by: pubsub@shakespeare.lit, from=sess-man@shakespeare.lit, to=null, DATA=<iq id="subscriptions1" to="pubsub.shakespeare.lit" type="get" xmlns="jabber:client" from="francisco@denmark.lit/barracks">
<pubsub xmlns="http://jabber.org/protocol/pubsub">
  <subscriptions/></pubsub></iq>, SIZE=207, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=get
2016-04-25 07:38:55.553 [in_2-pubsub]      PubSubComponentClustered.processPacket()  FINEST: Received packet: from=sess-man@shakespeare.lit, to=null, DATA=<iq id="subscriptions1" to="pubsub.shakespeare.lit" type="get" xmlns="jabber:client" from="francisco@denmark.lit/barracks">
<pubsub xmlns="http://jabber.org/protocol/pubsub">
  <subscriptions/></pubsub></iq>, SIZE=207, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=get
2016-04-25 07:38:55.553 [in_2-pubsub]      PubSubComponentClustered.processPacket()  FINEST: packet, processLocally: true, will be processed by nodes: [pubsub@shakespeare.lit]
2016-04-25 07:38:55.554 [in_2-pubsub]      PubSubDAOJDBC.getUserSubscriptions()  FINEST: Getting user subs: serviceJid: pubsub.shakespeare.lit, jid: francisco@shakespeare.lit
2016-04-25 07:38:55.557 [in_2-pubsub]      AbstractComponent.processStanzaPacket()  SEVERE: tigase.pubsub.repository.RepositoryException: User affiliations reading error when processing from=sess-man@shakespeare.lit, to=null, DATA=<iq id="subscriptions1" to="pubsub.shakespeare.lit" type="get" xmlns="jabber:client" from="francisco@denmark.lit/barracks">
<pubsub xmlns="http://jabber.org/protocol/pubsub">
  <subscriptions/></pubsub></iq>, SIZE=207, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=get
java.lang.RuntimeException: tigase.pubsub.repository.RepositoryException: User affiliations reading error
        at tigase.pubsub.modules.RetrieveSubscriptionsModule.process(RetrieveSubscriptionsModule.java:140)
        at tigase.component2.modules.ModulesManager.process(ModulesManager.java:87)
        at tigase.component2.AbstractComponent.processStanzaPacket(AbstractComponent.java:221)
        at tigase.component2.AbstractComponent.processPacket(AbstractComponent.java:209)
        at tigase.pubsub.PubSubComponent.processPacket(PubSubComponent.java:599)
        at tigase.pubsub.cluster.PubSubComponentClustered.processPacket(SourceFile:129)
        at tigase.server.AbstractMessageReceiver$QueueListener.run(AbstractMessageReceiver.java:1424)
Caused by: tigase.pubsub.repository.RepositoryException: User affiliations reading error
        at tigase.pubsub.repository.PubSubDAOJDBC.getUserSubscriptions(PubSubDAOJDBC.java:625)
        at tigase.pubsub.repository.PubSubDAOPool.getUserSubscriptions(PubSubDAOPool.java:381)
        at tigase.pubsub.modules.RetrieveSubscriptionsModule.process(RetrieveSubscriptionsModule.java:112)
        at tigase.component2.modules.ModulesManager.process(ModulesManager.java:87)
        at tigase.component2.AbstractComponent.processStanzaPacket(AbstractComponent.java:221)
        at tigase.component2.AbstractComponent.processPacket(AbstractComponent.java:209)
        at tigase.pubsub.PubSubComponent.processPacket(PubSubComponent.java:599)
        at tigase.pubsub.cluster.PubSubComponentClustered.processPacket(SourceFile:129)
        at tigase.server.AbstractMessageReceiver$QueueListener.run(AbstractMessageReceiver.java:1424)
Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: No operations allowed after statement closed.
        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57)
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
        at java.lang.reflect.Constructor.newInstance(Constructor.java:526)
        at com.mysql.jdbc.Util.handleNewInstance(Util.java:406)
        at com.mysql.jdbc.Util.getInstance(Util.java:381)
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1012)
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:986)
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:981)
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:926)
        at com.mysql.jdbc.StatementImpl.checkClosed(StatementImpl.java:405)
        at com.mysql.jdbc.PreparedStatement.setString(PreparedStatement.java:4374)
        at tigase.pubsub.repository.PubSubDAOJDBC.getUserSubscriptions(PubSubDAOJDBC.java:613)
        at tigase.pubsub.repository.PubSubDAOPool.getUserSubscriptions(PubSubDAOPool.java:381)
        at tigase.pubsub.modules.RetrieveSubscriptionsModule.process(RetrieveSubscriptionsModule.java:112)
        at tigase.component2.modules.ModulesManager.process(ModulesManager.java:87)
        at tigase.component2.AbstractComponent.processStanzaPacket(AbstractComponent.java:221)
        at tigase.component2.AbstractComponent.processPacket(AbstractComponent.java:209)
        at tigase.pubsub.PubSubComponent.processPacket(PubSubComponent.java:599)
        at tigase.pubsub.cluster.PubSubComponentClustered.processPacket(SourceFile:129)
        at tigase.server.AbstractMessageReceiver$QueueListener.run(AbstractMessageReceiver.java:1424)
2016-04-25 07:38:55.558 [in_2-pubsub]      AbstractComponent.sendException()  FINEST:   Sending back: from=pubsub.shakespeare.lit, to=sess-man@shakespeare.lit, DATA=<iq from="pubsub.shakespeare.lit" to="francisco@denmark.lit/barracks" type="error" id="subscriptions1" xmlns="jabber:client"><pubsub xmlns="http://jabber.org/protocol/pubsub">
  <subscriptions/></pubsub><error type="wait" code="500"><internal-server-error xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/></error></iq>, SIZE=314, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=error
2016-04-25 07:38:55.558 [in_2-pubsub]      AbstractComponent$1.write()        FINER:    Sent: <iq from="pubsub.shakespeare.lit" to="francisco@denmark.lit/barracks" type="error" id="subscriptions1" xmlns="jabber:client"><pubsub xmlns="http://jabber.org/protocol/pubsub">
  <subscriptions/></pubsub><error type="wait" code="500"><internal-server-error xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/></error></iq>
2016-04-25 07:38:55.559 [in_2-message-router]  MessageRouter.processPacket()  FINEST:   Processing packet: from=pubsub.shakespeare.lit, to=sess-man@shakespeare.lit, DATA=<iq from="pubsub.shakespeare.lit" to="francisco@denmark.lit/barracks" type="error" id="subscriptions1" xmlns="jabber:client"><pubsub xmlns="http://jabber.org/protocol/pubsub">
  <subscriptions/></pubsub><error type="wait" code="500"><internal-server-error xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/></error></iq>, SIZE=314, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=error
2016-04-25 07:38:55.559 [in_2-message-router]  MessageRouter.getLocalComponent()  FINEST: Called for : francisco@denmark.lit/barracks
2016-04-25 07:38:55.559 [in_2-message-router]  MessageRouter.getLocalComponent()  FINEST: No componentID matches (fast lookup against exact address): francisco@denmark.lit/barracks, for map: [monitor@shakespeare.lit, ws2s@shakespeare.lit, pubsub@shakespeare.lit, stats@shakespeare.lit, message-archive@shakespeare.lit, basic-conf@shakespeare.lit, muc@shakespeare.lit, s2s@shakespeare.lit, sess-man@shakespeare.lit, vhost-man@shakespeare.lit, http@shakespeare.lit, ssend@shakespeare.lit, srecv@shakespeare.lit, c2s@shakespeare.lit, bosh@shakespeare.lit]; trying VHost lookup
2016-04-25 07:38:55.560 [in_2-message-router]  MessageRouter.getLocalComponent()  FINEST: No component name matches (VHost lookup against component name): francisco@denmark.lit/barracks, for map: [ssend, c2s, basic-conf, s2s, bosh, vhost-man, sess-man, ws2s, message-router, message-archive, pubsub, stats, srecv, monitor, http, muc], for all VHosts: [shakespeare.lit, shakespeare.lit]; trying other forms of addressing
2016-04-25 07:38:55.560 [in_2-message-router]  MessageRouter.getLocalComponent()  FINEST: Component match failed: francisco@denmark.lit/barracks, for comp: [ssend, c2s, basic-conf, s2s, bosh, vhost-man, sess-man, ws2s, message-router, message-archive, pubsub, stats, srecv, monitor, http, muc], basename: shakespeare.lit
2016-04-25 07:38:55.560 [in_2-message-router]  MessageRouter.getLocalComponent()  FINEST: Called for : sess-man@shakespeare.lit
2016-04-25 07:38:55.560 [in_2-message-router]  MessageRouter.processPacket()  FINEST:   1. Packet will be processed by: sess-man@shakespeare.lit, from=pubsub.shakespeare.lit, to=sess-man@shakespeare.lit, DATA=<iq from="pubsub.shakespeare.lit" to="francisco@denmark.lit/barracks" type="error" id="subscriptions1" xmlns="jabber:client"><pubsub xmlns="http://jabber.org/protocol/pubsub">
  <subscriptions/></pubsub><error type="wait" code="500"><internal-server-error xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/></error></iq>, SIZE=314, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=error
2016-04-25 07:38:55.561 [in_13-sess-man]   SessionManager.processPacket()     FINEST:   Received packet: from=pubsub.shakespeare.lit, to=sess-man@shakespeare.lit, DATA=<iq from="pubsub.shakespeare.lit" to="francisco@denmark.lit/barracks" type="error" id="subscriptions1" xmlns="jabber:client"><pubsub xmlns="http://jabber.org/protocol/pubsub">CData size: 3<subscriptions/></pubsub><error type="wait" code="500"><internal-server-error xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/></error></iq>, SIZE=314, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=error
2016-04-25 07:38:55.561 [in_13-sess-man]   SessionManager.getXMPPResourceConnection()  FINEST: Searching for resource connection for: francisco@denmark.lit/barracks
2016-04-25 07:38:55.561 [in_13-sess-man]   SessionManager.getResourceConnection()  FINEST: Session not null, searching session for jid: francisco@denmark.lit/barracks
2016-04-25 07:38:55.561 [in_13-sess-man]   SessionManager.getResourceConnection()  FINEST: Found session: XMPPResourceConnection=[user_jid=francisco@denmark.lit/barracks, packets=49, connectioId=c2s@shakespeare.lit/192.168.44.81_5222_192.168.36.151_5751, domain=shakespeare.lit, authState=AUTHORIZED, isAnon=false, isTmp=false], for jid: francisco@denmark.lit/barracks
2016-04-25 07:38:55.561 [in_13-sess-man]   SessionManager.processPacket()     FINEST:   processing packet: from=pubsub.shakespeare.lit, to=sess-man@shakespeare.lit, DATA=<iq from="pubsub.shakespeare.lit" to="francisco@denmark.lit/barracks" type="error" id="subscriptions1" xmlns="jabber:client"><pubsub xmlns="http://jabber.org/protocol/pubsub">CData size: 3<subscriptions/></pubsub><error type="wait" code="500"><internal-server-error xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/></error></iq>, SIZE=314, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=error, connection: XMPPResourceConnection=[user_jid=francisco@denmark.lit/barracks, packets=49, connectioId=c2s@shakespeare.lit/192.168.44.81_5222_192.168.36.151_5751, domain=shakespeare.lit, authState=AUTHORIZED, isAnon=false, isTmp=false]
2016-04-25 07:38:55.562 [in_13-sess-man]   StartTLS.preProcess()              FINEST:   VHost: Domain: shakespeare.lit, enabled: true, anonym: false, register: true, maxusers: 0, tls: false, s2sSecret: 715dbc5e-07f9-42d1-b1dd-0522100d3135, domainFilter: ALL, domainFilterDomains: null, c2sPortsAllowed: null, saslAllowedMechanisms: null
2016-04-25 07:38:55.562 [in_13-sess-man]   JabberIqPrivacy.allowed()          FINEST:   Using privcy list: null
2016-04-25 07:38:55.562 [default-handler Queue Worker 2]  SessionManager$DefaultHandlerProc.process()  FINEST: Executing default packet handler for: from=pubsub.shakespeare.lit, to=sess-man@shakespeare.lit, DATA=<iq from="pubsub.shakespeare.lit" to="francisco@denmark.lit/barracks" type="error" id="subscriptions1" xmlns="jabber:client"><pubsub xmlns="http://jabber.org/protocol/pubsub">
  <subscriptions/></pubsub><error type="wait" code="500"><internal-server-error xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/></error></iq>, SIZE=314, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=error
2016-04-25 07:38:55.562 [default-handler Queue Worker 2]  PacketDefaultHandler.process()  FINEST: Processing packet: from=pubsub.shakespeare.lit, to=sess-man@shakespeare.lit, DATA=<iq from="pubsub.shakespeare.lit" to="francisco@denmark.lit/barracks" type="error" id="subscriptions1" xmlns="jabber:client"><pubsub xmlns="http://jabber.org/protocol/pubsub">CData size: 3<subscriptions/></pubsub><error type="wait" code="500"><internal-server-error xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/></error></iq>, SIZE=314, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=error
2016-04-25 07:38:55.562 [default-handler Queue Worker 2]  PacketDefaultHandler.process()  FINEST: Delivering message, packet: from=pubsub.shakespeare.lit, to=sess-man@shakespeare.lit, DATA=<iq from="pubsub.shakespeare.lit" to="francisco@denmark.lit/barracks" type="error" id="subscriptions1" xmlns="jabber:client"><pubsub xmlns="http://jabber.org/protocol/pubsub">
  <subscriptions/></pubsub><error type="wait" code="500"><internal-server-error xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/></error></iq>, SIZE=314, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=error, to session: XMPPResourceConnection=[user_jid=francisco@denmark.lit/barracks, packets=50, connectioId=c2s@shakespeare.lit/192.168.44.81_5222_192.168.36.151_5751, domain=shakespeare.lit, authState=AUTHORIZED, isAnon=false, isTmp=false]
2016-04-25 07:38:55.562 [default-handler Queue Worker 2]  JabberIqPrivacy.filter()  FINEST: Checking outbound packet: from=sess-man@shakespeare.lit, to=c2s@shakespeare.lit/192.168.44.81_5222_192.168.36.151_5751, DATA=<iq from="pubsub.shakespeare.lit" to="francisco@denmark.lit/barracks" type="error" id="subscriptions1" xmlns="jabber:client"><pubsub xmlns="http://jabber.org/protocol/pubsub">
  <subscriptions/></pubsub><error type="wait" code="500"><internal-server-error xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/></error></iq>, SIZE=314, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=error
2016-04-25 07:38:55.563 [default-handler Queue Worker 2]  JabberIqPrivacy.allowed()  FINEST: Using privcy list: null
2016-04-25 07:38:55.563 [in_3-message-router]  MessageRouter.processPacket()  FINEST:   Processing packet: from=sess-man@shakespeare.lit, to=c2s@shakespeare.lit/192.168.44.81_5222_192.168.36.151_5751, DATA=<iq from="pubsub.shakespeare.lit" to="francisco@denmark.lit/barracks" type="error" id="subscriptions1" xmlns="jabber:client"><pubsub xmlns="http://jabber.org/protocol/pubsub">
  <subscriptions/></pubsub><error type="wait" code="500"><internal-server-error xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/></error></iq>, SIZE=314, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=error
2016-04-25 07:38:55.563 [in_3-message-router]  MessageRouter.getLocalComponent()  FINEST: Called for : francisco@denmark.lit/barracks
2016-04-25 07:38:55.563 [in_3-message-router]  MessageRouter.getLocalComponent()  FINEST: No componentID matches (fast lookup against exact address): francisco@denmark.lit/barracks, for map: [monitor@shakespeare.lit, ws2s@shakespeare.lit, pubsub@shakespeare.lit, stats@shakespeare.lit, message-archive@shakespeare.lit, basic-conf@shakespeare.lit, muc@shakespeare.lit, s2s@shakespeare.lit, sess-man@shakespeare.lit, vhost-man@shakespeare.lit, http@shakespeare.lit, ssend@shakespeare.lit, srecv@shakespeare.lit, c2s@shakespeare.lit, bosh@shakespeare.lit]; trying VHost lookup
2016-04-25 07:38:55.563 [in_3-message-router]  MessageRouter.getLocalComponent()  FINEST: No component name matches (VHost lookup against component name): francisco@denmark.lit/barracks, for map: [ssend, c2s, basic-conf, s2s, bosh, vhost-man, sess-man, ws2s, message-router, message-archive, pubsub, stats, srecv, monitor, http, muc], for all VHosts: [shakespeare.lit, shakespeare.lit]; trying other forms of addressing
2016-04-25 07:38:55.563 [in_3-message-router]  MessageRouter.getLocalComponent()  FINEST: Component match failed: francisco@denmark.lit/barracks, for comp: [ssend, c2s, basic-conf, s2s, bosh, vhost-man, sess-man, ws2s, message-router, message-archive, pubsub, stats, srecv, monitor, http, muc], basename: shakespeare.lit
2016-04-25 07:38:55.564 [in_3-message-router]  MessageRouter.getLocalComponent()  FINEST: Called for : c2s@shakespeare.lit/192.168.44.81_5222_192.168.36.151_5751
2016-04-25 07:38:55.564 [in_3-message-router]  MessageRouter.getLocalComponent()  FINEST: No componentID matches (fast lookup against exact address): c2s@shakespeare.lit/192.168.44.81_5222_192.168.36.151_5751, for map: [monitor@shakespeare.lit, ws2s@shakespeare.lit, pubsub@shakespeare.lit, stats@shakespeare.lit, message-archive@shakespeare.lit, basic-conf@shakespeare.lit, muc@shakespeare.lit, s2s@shakespeare.lit, sess-man@shakespeare.lit, vhost-man@shakespeare.lit, http@shakespeare.lit, ssend@shakespeare.lit, srecv@shakespeare.lit, c2s@shakespeare.lit, bosh@shakespeare.lit]; trying VHost lookup
2016-04-25 07:38:55.564 [in_3-message-router]  MessageRouter.processPacket()  FINEST:   1. Packet will be processed by: c2s@shakespeare.lit, from=sess-man@shakespeare.lit, to=c2s@shakespeare.lit/192.168.44.81_5222_192.168.36.151_5751, DATA=<iq from="pubsub.shakespeare.lit" to="francisco@denmark.lit/barracks" type="error" id="subscriptions1" xmlns="jabber:client"><pubsub xmlns="http://jabber.org/protocol/pubsub">
  <subscriptions/></pubsub><error type="wait" code="500"><internal-server-error xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/></error></iq>, SIZE=314, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=error
2016-04-25 07:38:55.564 [in_3-c2s]         ClientConnectionManager.processPacket()  FINEST: Processing packet: from=sess-man@shakespeare.lit, to=c2s@shakespeare.lit/192.168.44.81_5222_192.168.36.151_5751, DATA=<iq from="pubsub.shakespeare.lit" to="francisco@denmark.lit/barracks" type="error" id="subscriptions1" xmlns="jabber:client"><pubsub xmlns="http://jabber.org/protocol/pubsub">CData size: 3<subscriptions/></pubsub><error type="wait" code="500"><internal-server-error xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/></error></iq>, SIZE=314, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=error
2016-04-25 07:38:55.564 [in_3-c2s]         ConnectionManager.writePacketToSocket()  FINEST: c2s@shakespeare.lit/192.168.44.81_5222_192.168.36.151_5751, type: accept, Socket: TLS: c2s@shakespeare.lit/192.168.44.81_5222_192.168.36.151_5751 Socket[addr=/192.168.36.151,port=5751,localport=5222], jid: francisco@denmark.lit/barracks, Writing packet: from=sess-man@shakespeare.lit, to=c2s@shakespeare.lit/192.168.44.81_5222_192.168.36.151_5751, DATA=<iq from="pubsub.shakespeare.lit" to="francisco@denmark.lit/barracks" type="error" id="subscriptions1" xmlns="jabber:client"><pubsub xmlns="http://jabber.org/protocol/pubsub">
  <subscriptions/></pubsub><error type="wait" code="500"><internal-server-error xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/></error></iq>, SIZE=314, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=error
2016-04-25 07:38:55.565 [in_13-sess-man]   SessionManager.processPacket()     FINEST:   Packet processed by: [default-handler]
2016-04-25 07:38:57.619 [Watchdog - c2s]   ConnectionManager.writePacketToSocket()  FINEST: c2s@shakespeare.lit/192.168.44.81_5222_192.168.36.152_51151, type: accept, Socket: c2s@shakespeare.lit/192.168.44.81_5222_192.168.36.152_51151 Socket[addr=/192.168.36.152,port=51151,localport=5222], jid: francisco@denmark.lit/barracks, Writing packet: from=null, to=null, DATA=<iq type="get" to="francisco@denmark.lit/barracks" id="tigase-ping" from="shakespeare.lit"><ping xmlns="urn:xmpp:ping"/></iq>, SIZE=117, XMLNS=null, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=get
2016-04-25 07:38:57.809 [pool-17-thread-5]  ClientConnectionManager.processSocketData()  FINEST: Processing socket data: from=null, to=null, DATA=<iq id="tigase-ping" to="shakespeare.lit" type="result" from="francisco@denmark.lit/barracks" xmlns="jabber:client"/>, SIZE=109, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=result from connection: c2s@shakespeare.lit/192.168.44.81_5222_192.168.36.152_51151
2016-04-25 07:38:57.809 [in_1-message-router]  MessageRouter.processPacket()  FINEST:   Processing packet: from=c2s@shakespeare.lit/192.168.44.81_5222_192.168.36.152_51151, to=sess-man@shakespeare.lit, DATA=<iq id="tigase-ping" to="shakespeare.lit" type="result" xmlns="jabber:client"/>, SIZE=75, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=result
2016-04-25 07:38:57.809 [in_1-message-router]  MessageRouter.getLocalComponent()  FINEST: Called for : shakespeare.lit
2016-04-25 07:38:57.810 [in_1-message-router]  MessageRouter.getLocalComponent()  FINEST: No componentID matches (fast lookup against exact address): shakespeare.lit, for map: [monitor@shakespeare.lit, ws2s@shakespeare.lit, pubsub@shakespeare.lit, stats@shakespeare.lit, message-archive@shakespeare.lit, basic-conf@shakespeare.lit, muc@shakespeare.lit, s2s@shakespeare.lit, sess-man@shakespeare.lit, vhost-man@shakespeare.lit, http@shakespeare.lit, ssend@shakespeare.lit, srecv@shakespeare.lit, c2s@shakespeare.lit, bosh@shakespeare.lit]; trying VHost lookup
2016-04-25 07:38:57.810 [in_1-message-router]  MessageRouter.getLocalComponent()  FINEST: No component name matches (VHost lookup against component name): shakespeare.lit, for map: [ssend, c2s, basic-conf, s2s, bosh, vhost-man, sess-man, ws2s, message-router, message-archive, pubsub, stats, srecv, monitor, http, muc], for all VHosts: [shakespeare.lit, shakespeare.lit]; trying other forms of addressing
2016-04-25 07:38:57.810 [in_1-message-router]  MessageRouter.getLocalComponent()  FINEST: Component match failed: shakespeare.lit, for comp: [ssend, c2s, basic-conf, s2s, bosh, vhost-man, sess-man, ws2s, message-router, message-archive, pubsub, stats, srecv, monitor, http, muc], basename: shakespeare.lit
2016-04-25 07:38:57.811 [in_1-message-router]  MessageRouter.getLocalComponent()  FINEST: Called for : sess-man@shakespeare.lit
2016-04-25 07:38:57.811 [in_1-message-router]  MessageRouter.processPacket()  FINEST:   1. Packet will be processed by: sess-man@shakespeare.lit, from=c2s@shakespeare.lit/192.168.44.81_5222_192.168.36.152_51151, to=sess-man@shakespeare.lit, DATA=<iq id="tigase-ping" to="shakespeare.lit" type="result" xmlns="jabber:client"/>, SIZE=75, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=result
2016-04-25 07:38:57.811 [in_5-sess-man]    SessionManager.processPacket()     FINEST:   Received packet: from=c2s@shakespeare.lit/192.168.44.81_5222_192.168.36.152_51151, to=sess-man@shakespeare.lit, DATA=<iq id="tigase-ping" to="shakespeare.lit" type="result" xmlns="jabber:client"/>, SIZE=75, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=result
2016-04-25 07:38:57.811 [in_5-sess-man]    SessionManager.processPacket()     FINEST:   processing packet: from=c2s@shakespeare.lit/192.168.44.81_5222_192.168.36.152_51151, to=sess-man@shakespeare.lit, DATA=<iq id="tigase-ping" to="shakespeare.lit" type="result" xmlns="jabber:client"/>, SIZE=75, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=result, connection: XMPPResourceConnection=[user_jid=francisco@denmark.lit/barracks, packets=146, connectioId=c2s@shakespeare.lit/192.168.44.81_5222_192.168.36.152_51151, domain=shakespeare.lit, authState=AUTHORIZED, isAnon=false, isTmp=false]
2016-04-25 07:38:57.812 [in_5-sess-man]    StartTLS.preProcess()              FINEST:   VHost: Domain: shakespeare.lit, enabled: true, anonym: false, register: true, maxusers: 0, tls: false, s2sSecret: 715dbc5e-07f9-42d1-b1dd-0522100d3135, domainFilter: ALL, domainFilterDomains: null, c2sPortsAllowed: null, saslAllowedMechanisms: null
2016-04-25 07:38:57.812 [in_5-sess-man]    BindResource.preProcess()          FINEST:   Setting correct from attribute: francisco@denmark.lit/barracks
2016-04-25 07:38:57.812 [in_5-sess-man]    SessionManager.processAdminsOrDomains()  FINER: IQ result packet addressed directly to server and not handle by any plugin: from=c2s@shakespeare.lit/192.168.44.81_5222_192.168.36.152_51151, to=sess-man@shakespeare.lit, DATA=<iq id="tigase-ping" to="shakespeare.lit" type="result" xmlns="jabber:client" from="francisco@denmark.lit/barracks"/>, SIZE=109, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=result
2016-04-25 07:38:57.812 [in_5-sess-man]    SessionManager.processPacket()     FINEST:   Packet processed by: [iq-result-to-server]

tigase-console:

tigase.pubsub.repository.RepositoryException: User affiliations reading error
        at tigase.pubsub.repository.PubSubDAOJDBC.getUserSubscriptions(PubSubDAOJDBC.java:625)
        at tigase.pubsub.repository.PubSubDAOPool.getUserSubscriptions(PubSubDAOPool.java:381)
        at tigase.pubsub.modules.RetrieveSubscriptionsModule.process(RetrieveSubscriptionsModule.java:112)
        at tigase.component2.modules.ModulesManager.process(ModulesManager.java:87)
        at tigase.component2.AbstractComponent.processStanzaPacket(AbstractComponent.java:221)
        at tigase.component2.AbstractComponent.processPacket(AbstractComponent.java:209)
        at tigase.pubsub.PubSubComponent.processPacket(PubSubComponent.java:599)
        at tigase.pubsub.cluster.PubSubComponentClustered.processPacket(SourceFile:129)
        at tigase.server.AbstractMessageReceiver$QueueListener.run(AbstractMessageReceiver.java:1424)
Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: No operations allowed after statement closed.
        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57)
       at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
        at java.lang.reflect.Constructor.newInstance(Constructor.java:526)
        at com.mysql.jdbc.Util.handleNewInstance(Util.java:406)
        at com.mysql.jdbc.Util.getInstance(Util.java:381)
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1012)
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:986)
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:981)
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:926)
        at com.mysql.jdbc.StatementImpl.checkClosed(StatementImpl.java:405)
        at com.mysql.jdbc.PreparedStatement.setString(PreparedStatement.java:4374)
        at tigase.pubsub.repository.PubSubDAOJDBC.getUserSubscriptions(PubSubDAOJDBC.java:613)
        ... 8 more
2016-04-25 07:27:32.620 [in_1-pubsub]      AbstractComponent.processStanzaPacket()  SEVERE: tigase.pubsub.repository.RepositoryException: User affiliations reading error when processing from=sess-man@x5.lopl.net, to=null, DATA=<iq id="subscriptions1" to="pubsub.x5.lopl.net" type="get" xmlns="jabber:client" from="989212276979@x5.lopl.net/Dalaho-PC">
<pubsub xmlns="http://jabber.org/protocol/pubsub">
  <subscriptions/></pubsub></iq>, SIZE=207, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=get
java.lang.RuntimeException: tigase.pubsub.repository.RepositoryException: User affiliations reading error
        at tigase.pubsub.modules.RetrieveSubscriptionsModule.process(RetrieveSubscriptionsModule.java:140)
        at tigase.component2.modules.ModulesManager.process(ModulesManager.java:87)
        at tigase.component2.AbstractComponent.processStanzaPacket(AbstractComponent.java:221)
        at tigase.component2.AbstractComponent.processPacket(AbstractComponent.java:209)
        at tigase.pubsub.PubSubComponent.processPacket(PubSubComponent.java:599)
        at tigase.pubsub.cluster.PubSubComponentClustered.processPacket(SourceFile:129)
        at tigase.server.AbstractMessageReceiver$QueueListener.run(AbstractMessageReceiver.java:1424)
Caused by: tigase.pubsub.repository.RepositoryException: User affiliations reading error
        at tigase.pubsub.repository.PubSubDAOJDBC.getUserSubscriptions(PubSubDAOJDBC.java:625)
        at tigase.pubsub.repository.PubSubDAOPool.getUserSubscriptions(PubSubDAOPool.java:381)
        at tigase.pubsub.modules.RetrieveSubscriptionsModule.process(RetrieveSubscriptionsModule.java:112)
        at tigase.component2.modules.ModulesManager.process(ModulesManager.java:87)
        at tigase.component2.AbstractComponent.processStanzaPacket(AbstractComponent.java:221)
        at tigase.component2.AbstractComponent.processPacket(AbstractComponent.java:209)
        at tigase.pubsub.PubSubComponent.processPacket(PubSubComponent.java:599)
        at tigase.pubsub.cluster.PubSubComponentClustered.processPacket(SourceFile:129)
        at tigase.server.AbstractMessageReceiver$QueueListener.run(AbstractMessageReceiver.java:1424)
Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: No operations allowed after statement closed.
        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57)
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
        at java.lang.reflect.Constructor.newInstance(Constructor.java:526)
        at com.mysql.jdbc.Util.handleNewInstance(Util.java:406)
        at com.mysql.jdbc.Util.getInstance(Util.java:381)
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1012)
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:986)
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:981)
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:926)
        at com.mysql.jdbc.StatementImpl.checkClosed(StatementImpl.java:405)
        at com.mysql.jdbc.PreparedStatement.setString(PreparedStatement.java:4374)
        at tigase.pubsub.repository.PubSubDAOJDBC.getUserSubscriptions(PubSubDAOJDBC.java:613)
        at tigase.pubsub.repository.PubSubDAOPool.getUserSubscriptions(PubSubDAOPool.java:381)
        at tigase.pubsub.modules.RetrieveSubscriptionsModule.process(RetrieveSubscriptionsModule.java:112)
        at tigase.component2.modules.ModulesManager.process(ModulesManager.java:87)
        at tigase.component2.AbstractComponent.processStanzaPacket(AbstractComponent.java:221)
        at tigase.component2.AbstractComponent.processPacket(AbstractComponent.java:209)
        at tigase.pubsub.PubSubComponent.processPacket(PubSubComponent.java:599)
        at tigase.pubsub.cluster.PubSubComponentClustered.processPacket(SourceFile:129)
        at tigase.server.AbstractMessageReceiver$QueueListener.run(AbstractMessageReceiver.java:1424)
Mon Apr 25 07:27:40 BST 2016 INFO: Profiler Event: [QUERY]      at tigase.db.jdbc.JDBCRepository.getData(JDBCRepository.java:258) duration: 1 ms, connection-id: 30709, statement-id: 180, resultset-id: 45795, message: select pval from tig_pairs where (nid = 3) AND (pkey = 'vhosts-lists')
Mon Apr 25 07:27:40 BST 2016 INFO: Profiler Event: [FETCH]      at tigase.db.jdbc.JDBCRepository.getData(JDBCRepository.java:258) duration: 0 ms, connection-id: 30709, statement-id: 180, resultset-id: 45795

Added by Wojciech Kapcia TigaseTeam almost 3 years ago

As I said - please include full server logs - you are only including the same error message, which is most likely result of some earlier processing.

Please also include your full configuration.

(1)

Added by Ehsan Mozaffari almost 3 years ago

Sorry for any inconvenience this may cause you.

I attached full server logs and full configurations.

(1)

Added by Wojciech Kapcia TigaseTeam almost 3 years ago

First of all - you are making sucesfull queries for the subscriptions:

$ grep "Profiler Event: .QUERY..*getUserSubscriptions" /Users/wojtek/Downloads/tigase-console-2.log | wc -l
     215

However, as expected - previous logs reveals the actual cause of the problem:

Thu Apr 21 01:36:50 BST 2016 INFO: Profiler Event: [FETCH]      at tigase.db.jdbc.JDBCRepository.getUserUID(JDBCRepository.java:466) duration: 0 ms, connection-id: 30710, statement-id: 60, resultset-id:
 11719
tigase.pubsub.repository.RepositoryException: User affiliations reading error
        at tigase.pubsub.repository.PubSubDAOJDBC.getUserAffiliations(PubSubDAOJDBC.java:597)
        at tigase.pubsub.repository.PubSubDAOPool.getUserAffiliations(PubSubDAOPool.java:366)
        at tigase.pubsub.modules.RetrieveAffiliationsModule.process(RetrieveAffiliationsModule.java:110)
        at tigase.component2.modules.ModulesManager.process(ModulesManager.java:87)
        at tigase.component2.AbstractComponent.processStanzaPacket(AbstractComponent.java:221)
        at tigase.component2.AbstractComponent.processPacket(AbstractComponent.java:209)
        at tigase.pubsub.PubSubComponent.processPacket(PubSubComponent.java:599)
        at tigase.pubsub.cluster.PubSubComponentClustered.processPacket(SourceFile:129)
        at tigase.server.AbstractMessageReceiver$QueueListener.run(AbstractMessageReceiver.java:1424)
Caused by: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: The last packet successfully received from the server was 37,065,481 milliseconds ago.  The last packet sent successfully to the server was 37,065,481 milliseconds ago. is longer than the server configured value of 'wait_timeout'. You should consider either expiring and/or testing connection validity before use in your application, increasing the server configured values for client timeouts, or using the Connector/J connection property 'autoReconnect=true' to avoid this problem.
        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57)
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
        at java.lang.reflect.Constructor.newInstance(Constructor.java:526)
        at com.mysql.jdbc.Util.handleNewInstance(Util.java:406)
        at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:1119)
        at com.mysql.jdbc.MysqlIO.send(MysqlIO.java:3318)
        at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1940)
        at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2113)
        at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2693)
        at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2102)
        at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:2261)
        at com.mysql.jdbc.CallableStatement.executeQuery(CallableStatement.java:912)
        at tigase.pubsub.repository.PubSubDAOJDBC.getUserAffiliations(PubSubDAOJDBC.java:588)
        ... 8 more
Caused by: java.net.SocketException: Broken pipe
        at java.net.SocketOutputStream.socketWrite0(Native Method)
        at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:113)
        at java.net.SocketOutputStream.write(SocketOutputStream.java:159)
        at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
        at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)
        at com.mysql.jdbc.MysqlIO.send(MysqlIO.java:3299)
        ... 15 more

As described in the exception, there is a problem with the timeouting the connection. The problem is - this shouldn't happen as PubSub component periodically checks the connection.

As suggested above, you could try appending autoReconnect=true to your JDBC string, but we haven't tested this solution - it still looks more like database problem.

What actual database and version are you using? With what configuration?

(1)

Added by Ehsan Mozaffari almost 3 years ago

I appended autoReconnect=true in my @init.properties@.

My MySQL version is: 5.1.73 Source distribution

MySQL configuration:

#
# The MySQL database server configuration file.
#
# You can copy this to one of:
# - "/etc/mysql/my.cnf" to set global options,
# - "~/.my.cnf" to set user-specific options.
# 
# One can use all long options that the program supports.
# Run program with --help to get a list of available options and with
# --print-defaults to see which it would actually understand and use.
#
# For explanations see
# http://dev.mysql.com/doc/mysql/en/server-system-variables.html

# This will be passed to all mysql clients
# It has been reported that passwords should be enclosed with ticks/quotes
# escpecially if they contain "#" chars...
# Remember to edit /etc/mysql/debian.cnf when changing the socket location.
[client]
port        = 3306
socket      = /var/run/mysqld/mysqld.sock

# Here is entries for some specific programs
# The following values assume you have at least 32M ram

# This was formally known as [safe_mysqld]. Both versions are currently parsed.
[mysqld_safe]
socket      = /var/run/mysqld/mysqld.sock
nice        = 0

[mysqld]
#
# * Basic Settings
#
user        = mysql
pid-file    = /var/run/mysqld/mysqld.pid
socket      = /var/run/mysqld/mysqld.sock
port        = 3306
basedir     = /usr
datadir     = /var/lib/mysql
tmpdir      = /tmp
lc-messages-dir = /usr/share/mysql
skip-external-locking
#log=/var/query.log
#
# Instead of skip-networking the default is now to listen only on
# localhost which is more compatible and is not less secure.
#bind-address       = 127.0.0.1
#
# * Fine Tuning
#
key_buffer      = 16M
max_allowed_packet  = 16M
thread_stack        = 192K
thread_cache_size       = 8
# This replaces the startup script and checks MyISAM tables if needed
# the first time they are touched
myisam-recover         = BACKUP
#max_connections        = 100
#table_cache            = 64
#thread_concurrency     = 10
#
# * Query Cache Configuration
#
query_cache_limit   = 1M
query_cache_size        = 16M
#
# * Logging and Replication
#
# Both location gets rotated by the cronjob.
# Be aware that this log type is a performance killer.
# As of 5.1 you can enable the log at runtime!
general_log_file        = /var/log/mysql/mysql.log
general_log             = 1
#
# Error log - should be very few entries.
#
#log_error = /var/log/mysql/error.log
#
# Here you can see queries with especially long duration
#log_slow_queries   = /var/log/mysql/mysql-slow.log
#long_query_time = 2
#log-queries-not-using-indexes
#
# The following can be used as easy to replay backup logs or for replication.
# note: if you are setting up a replication slave, see README.Debian about
#       other settings you may need to change.
#server-id      = 1
#log_bin            = /var/log/mysql/mysql-bin.log
expire_logs_days    = 10
max_binlog_size         = 100M
#binlog_do_db       = include_database_name
#binlog_ignore_db   = include_database_name
#
# * InnoDB
#
# InnoDB is enabled by default with a 10MB datafile in /var/lib/mysql/.
# Read the manual for more InnoDB related options. There are many!
#
# * Security Features
#
# Read the manual, too, if you want chroot!
# chroot = /var/lib/mysql/
#
# For generating SSL certificates I recommend the OpenSSL GUI "tinyca".
#
# ssl-ca=/etc/mysql/cacert.pem
# ssl-cert=/etc/mysql/server-cert.pem
# ssl-key=/etc/mysql/server-key.pem



[mysqldump]
quick
quote-names
max_allowed_packet  = 16M

[mysql]
#no-auto-rehash # faster start of mysql but no tab completition

[isamchk]
key_buffer      = 16M

#
# * IMPORTANT: Additional settings that can override those from this file!
#   The files must end with '.cnf', otherwise they'll be ignored.
#
!includedir /etc/mysql/conf.d/

Added by Wojciech Kapcia TigaseTeam almost 3 years ago

Ehsan Mozaffari wrote:

I appended autoReconnect=true in my @init.properties@.

Has that solved the problem or improved it?

My MySQL version is: 5.1.73 Source distribution

MySQL configuration:

[...]

Can you try more recent version of the MySQL? For the Tigase 7.x we require using at least version 5.5 and recommend using version 5.6 (vide http://docs.tigase.org/tigase-server/snapshot/Administration_Guide/html_chunk/databasemgnt.html#_recommended_database_versions)

(1)

Added by Ehsan Mozaffari almost 3 years ago

Hi again,

After your last post about upgrading the MySQL we updated to the latest version 5.7.1 and the occurrence of the errors decreased, but the error still exist and we couldn't find the root cause of the problem.

Do you know what other issue may cause the problem?

(1)

Added by Wojciech Kapcia TigaseTeam almost 3 years ago

  • What variant of MySQL do you use exactly?

  • What operating system do you use? Have you checked system logs in case they were interfering?

    (1-13/13)