Project

General

Profile

S2S connection exception.

Slava Bendersky
Added over 5 years ago

Hello Everyone,

On pubsub getting exception about S2SAbstractProcessor.java

And I wonder about this statement

FINEST: Still no comp name matches: pubsub.networklab.loc
2013-12-09 17:20:00.607 [ConnectionOpenThread]  StreamOpen.serviceStarted()   FINEST:   CID: networklab.ca@pubsub.networklab.loc, null, type: connect, Socket: nullSocket[addr=/10.10.130.1,port=5269,localport=43791], jid: null, sending: <stream:stream xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:server' xmlns:db='jabber:server:dialback' from='networklab.ca' to='pubsub.networklab.loc' version='1.0'>
2013-12-09 17:20:00.607 [pool-11-thread-3]  S2SConnectionManager.xmppStreamOpened()  FINER: CID: null, null, type: accept, Socket: nullSocket[addr=/10.10.130.1,port=43791,localport=5269], jid: null, Stream opened: {to=pubsub.networklab.loc, xmlns:stream=http://etherx.jabber.org/streams, from=networklab.ca, xmlns=jabber:server, xmlns:db=jabber:server:dialback, version=1.0}
2013-12-09 17:20:00.607 [pool-11-thread-3]  StreamFeatures.streamOpened()     FINEST:   CID: null, null, type: accept, Socket: nullSocket[addr=/10.10.130.1,port=43791,localport=5269], jid: null, Sending stream features: <stream:features><dialback xmlns="urn:xmpp:features:dialback"><required/></dialback><starttls xmlns="urn:ietf:params:xml:ns:xmpp-tls"/></stream:features>
2013-12-09 17:20:00.607 [pool-11-thread-3]  S2SAbstractProcessor.generateStreamError()  FINEST: Called from: 
java.lang.Throwable
    at tigase.server.xmppserver.proc.S2SAbstractProcessor.generateStreamError(S2SAbstractProcessor.java:146)
    at tigase.server.xmppserver.proc.StreamOpen.streamOpened(StreamOpen.java:268)
    at tigase.server.xmppserver.S2SConnectionManager.xmppStreamOpened(S2SConnectionManager.java:645)
    at tigase.server.xmppserver.S2SConnectionManager.xmppStreamOpened(S2SConnectionManager.java:71)
    at tigase.xmpp.XMPPIOService.xmppStreamOpened(XMPPIOService.java:756)
    at tigase.xmpp.XMPPDomBuilderHandler.startElement(XMPPDomBuilderHandler.java:315)
    at tigase.xml.SimpleParser.parse(SimpleParser.java:314)
    at tigase.xmpp.XMPPIOService.processSocketData(XMPPIOService.java:636)
    at tigase.net.IOService.call(IOService.java:262)
    at tigase.net.IOService.call(IOService.java:103)
    at java.util.concurrent.FutureTask.run(FutureTask.java:262)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
    at java.util.concurrent.FutureTask.run(FutureTask.java:262)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at java.lang.Thread.run(Thread.java:744)
2013-12-09 17:20:00.608 [pool-11-thread-3]  S2SAbstractProcessor.generateStreamError()  FINEST: CID: null, null, type: accept, Socket: nullSocket[addr=/10.10.130.1,port=43791,localport=5269], jid: null, Sending stream error: <stream:error><host-unknown xmlns='urn:ietf:params:xml:ns:xmpp-streams'/></stream:error></stream:stream>
2013-12-09 17:20:00.608 [pool-11-thread-3]  ConnectionManager.serviceStopped()  FINER:  [[s2s]] Connection stopped: CID: null, null, type: accept, Socket: nullSocket[unconnected], jid: null


Replies (29)

Avatar?id=6023&size=32x32

Added by Artur Hefczyc TigaseTeam over 5 years ago

This log entry and the exception looks scary but everything is correct in the Tigase code. This is not a bug. We print this exception because this logic is executed very rarely and we wanted to be sure we handle it properly.

What is wrong then? The Tigase server configuration is incorrect.

An s2s connection is opened to the server for domain pubsub.networklab.ca but the Tigase is not configured to accept connections for this domain.

Added by Slava Bendersky over 5 years ago

This is asterisk device state share though pubsub. I have setup 2 nodes in cluster and trying setup correctly this service.

This is settings

# PubSub
--comp-name-1 = pubsub
--comp-class-1 = tigase.pubsub.PubSubComponent
pubsub/pubsub-repo-class = tigase.pubsub.repository.PubSubDAOJDBC
pubsub/pubsub-repo-url = jdbc:mysql://localhost/tigasedb?user=

Asterisk setting is

pubsub_node=pubsub.networklab.loc as far I know it should be pubsub + domain name.

Added by Slava Bendersky over 5 years ago

My question what is need set to fix that

Why S2S connection is not valid ?

2013-12-09 22:21:40.276 [pool-11-thread-6]  S2SConnectionManager.xmppStreamClosed()  FINER: CID: networklab.ca@pubsub.networklab.ca, null, type: connect, Socket: nullSocket[addr=/remote end site pub ip,port=5269,localport=46038], jid: null, Stream closed.

2013-12-09 22:21:40.276 [pool-11-thread-6] S2SConnectionManager.processSocketData() FINEST: Processing socket data: from=null, to=null, DATA=stream:error/stream:error, SIZE=88, XMLNS=null, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=null

2013-12-09 22:21:40.276 [pool-11-thread-6] S2SAbstractProcessor.generateStreamError() FINEST: Called from:

java.lang.Throwable

Avatar?id=6023&size=32x32

Added by Artur Hefczyc TigaseTeam over 5 years ago

Did you try to set this up with a single Tigase server in non-clustered mode? If you didn't please try this first. This is simpler scenario, hence easier to verify basic settings on Tigase and Asterix. Once this is working I suggest switching to cluster mode.

And in a cluster mode you do not use s2s connections between servers. If the Tigase server attempts to use s2s it means the cluster is not setup correctly. To help you out we need to see your complete config files.

Added by Slava Bendersky over 5 years ago

I tired standolone mode and it working good.

Here config

config-type = --gen-config-def
--admins = admin@networklab.ca
--virt-hosts = networklab.ca
--vhost-anonymous-enabled = false
--vhost-register-enabled = true
--vhost-tls-required = true
--vhost-max-users = 150
--debug = server,cluster
# Cluster mode
--cluster-mode = true
--cluster-nodes = xmpp02.networklab.loc::5270,xmpp01.networklab.loc:5270
# Authentication
--auth-db = tigase-custom
--auth-db-uri = jdbc:mysql://localhost/tigasedb?user=&password=
--user-db = mysql
--user-db-uri = jdbc:mysql://localhost/tigasedb?user=&password=&noAccessToProcedureBodies=true
# SSL
--ssl-container-class = tigase.io.SSLContextContainer
--ssl-certs-location = /etc/pki/tigase/certs
--ssl-def-cert-domain = networklab.ca
# Cross domain
--cross-domain-policy-file = /etc/tigase/cross-domain-policy.xml
# Plugins
--sm-plugins = +amp,-message,-msgoffline,+message-archive-xep-0136,+jabber:iq:auth,+urn:ietf:params:xml:ns:xmpp-sasl,+urn:ietf:params:xml:ns:xmpp-bind,+urn:ietf:params:xml:ns:xmpp-session,+jabber:iq:register,+roster-presence,+jabber:iq:version,+http://jabber.org/protocol/stats,+vcard-temp,+http://jabber.org/protocol/commands,+jabber:iq:private,+urn:xmpp:ping,+basic-filter,+domain-filter,+pep,-zlib
# History Monitoring
--monitoring = jmx:9521,http:9522
--stats-history = 2160,10
# Scripts
--script-dir = /usr/share/tigase/scripts/scripts/admin
# PubSub
--comp-name-1 = pubsub
--comp-class-1 = tigase.pubsub.PubSubComponent
# Muc
--comp-name-2 = muc
--comp-class-2 = tigase.cluster.VirtualComponent
# File transfer
--comp-name-3 = filetrans
--comp-class-3 = tigase.filetrans.FileTransComponent
--filetrans-ports = 2021
# Message archive
--comp-name-4 = message-archive
--comp-class-4 = tigase.archive.MessageArchiveComponent
# Client Access
--client-access-policy-file = /etc/tigase/client-access-policy.xml
# Bosh policy
--bosh-extra-headers-file = /etc/tigase/bosh-extra-headers.txt
# AMP
--amp-repo-uri = jdbc:mysql://cadbsrv01/tigasedb?user=&password=
--amp-security-level = STRICT
# Fedora/RHEL changes
# Change caations of certificates to be in line with the rest of the system
c2s/connections/tls/keys-store = /etc/pki/tigase/rsa-keystore
c2s/connections/tls/keys-store-password = 
c2s/connections/tls/def-cert-alias = networklab
s2s/connections/tls/keys-store=/etc/pki/tigase/truststore
s2s/connections/tls/keys-store-password=
s2s/connections/tls/def-cert-alias = networklab
bosh/connections/tls/keys-store=/etc/pki/tigase/rsa-keystore
bosh/connections/tls/keys-store-password = 
bosh/connections/tls/def-cert-alias = networklab
# logging should have limits and sane caation
basic-conf/logging/java.util.logging.FileHandler.limit = 100000000
basic-conf/logging/java.util.logging.FileHandler.count = 20
basic-conf/logging/java.util.logging.FileHandler.pattern = /var/log/tigase/tigase.log
basic-conf/config-dump-file = /etc/tigase/config-dump.properties
basic-conf/auth-repo-params/conn-valid-query = select 1
basic-conf/auth-repo-params/user-login-query = { call TigUserLoginPlainPw(?, ?) }
basic-conf/auth-repo-params/users-count-query = { call TigAllUsersCount() }
basic-conf/auth-repo-params/add-user-query = { call TigAddUserPlainPw(?, ?) }
basic-conf/auth-repo-params/del-user-query = { call TigRemoveUser(?) }
basic-conf/auth-repo-params/get-password-query = select user_pw from tig_users where user_id = ?
basic-conf/auth-repo-params/update-password-query = update tig_users set user_pw = ? where user_id = ?
basic-conf/auth-repo-params/user-logout-query = update tig_users set online_status = online_status - 1 where user_id = ?
basic-conf/auth-repo-params/non-sasl-mechs = password,digest
basic-conf/auth-repo-params/sasl-mechs = PLAIN,DIGEST-MD5
# Muc
muc/redirect-to = muc@xmpp2.networklab.loc
muc/disco-name = NeworkLabMultiChat
muc/disco-node =
muc/disco-type = text
muc/disco-category = conference
muc/disco-features = http://jabber.org/protocol/muc
# PubSub
pubsub/pubsub-repo-class = tigase.pubsub.repository.PubSubDAOJDBC
pubsub/pubsub-repo-url = jdbc:mysql://cadbsrv01/tigasedb?user=&password=

Added by Slava Bendersky over 5 years ago

As soon I am turning on asterisk with device state I stating see error

And pub sub connection trying go through S2SConnectionManager and not cluster.

 S2SAbstractProcessor.generateStreamError()  FINEST: CID: networklab.ca@pubsub.networklab.ca, null, type: connect, Socket: nullSocket[unconnected], jid: null, Sending stream error: <stream:error><improper-addressing xmlns='urn:ietf:params:xml:ns:xmpp-streams'/></stream:error></stream:stream>

Added by Slava Bendersky over 5 years ago

For test I commented out in asterisk config pubsubnode and right now getting error 501 on pubsub

xmpp02*CLI> 
[2013-12-11 06:21:06] ERROR[13149]: res_xmpp.c:1402 xmpp_pubsub_handle_error: PubSub Server error, 501
[2013-12-11 06:21:06] ERROR[13149]: res_xmpp.c:1402 xmpp_pubsub_handle_error: PubSub Server error, 501

2013-12-11 00:24:30.486 [in_7-c2s]         ConnectionManager.writePacketToSocket()  FINEST: c2s@xmpp01.networklab.ca/192.168.10.1_5222_192.168.10.2_38692, type: accept, Socket: TLS: c2s@xmpp01.networklab.ca/192.168.10.1_5222_192.168.10.2_38692 Socket[addr=/192.168.10.2,port=38692,localport=5222], jid: betta@networklab.ca/nl-status02, Writing packet: from=sess-man@xmpp01.networklab.ca, to=c2s@xmpp01.networklab.ca/192.168.10.1_5222_192.168.10.2_38692, DATA=<iq id="aaeby" xmlns="jabber:client" to="betta@networklab.ca/nl-status02" type="error"><pubsub xmlns="http://jabber.org/protocol/pubsub#owner"><affiliations node="device_state"><affiliation jid="delta@networklab.ca" affiliation="owner"/><affiliation jid="delta@networklab.ca/nl-status01" affiliation="owner"/></affiliations></pubsub><error code="501" type="cancel"><feature-not-implemented xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/><text xmlns="urn:ietf:params:xml:ns:xmpp-stanzas" xml:lang="en">Feature not supported yet.</text></error></iq>, SIZE=545, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=error

Added by Wojciech Kapcia TigaseTeam over 5 years ago

A few questions:

  • which version do you use?

  • what is the configuration on the second node? above one seems to be from node1 with pubsub running normally and muc forwarded to second one, does on the second one the scenario is reversed, i.e. muc running normally and pubsub running through VirtualComponent?

  • you've said:

Slava Bendersky wrote:

This is asterisk device state share though pubsub. I have setup 2 nodes in cluster and trying setup correctly this service.

pubsub_node=pubsub.networklab.loc as far I know it should be pubsub + domain name.

but your configuration is off a bit - don't know about asteriks that much, but doesn't look good - it should either be pubsub.networklab.ca (domain) or xmpp01.networklab.loc (hostname of the tigase node, but this is less likely to be correct IMHO).

Also - if you could provide full logs from both nodes from the even of starting asteriks (instead of single-line excerpts without context from which node they are comming) it would made investigating it easier.

Added by Slava Bendersky over 5 years ago

Version is snapshot of 5.2.

Asterisk server is setup per this wiki page.

https://wiki.asterisk.org/wiki/display/AST/Distributed+Device+State+with+XMPP+PubSub

VirtualComponent was a test case, but still not clear what I need to use for 2 node cluster.

[root@xmpp01 logrotate.d]# rpm -qa | grep tigase
tigase-server-5.2.1-4.el6.noarch

Yes, configuration on second node is the same, I corrected pubsub host name on asterisk to xmpp server name. Here log file, exactly from even when I issue reload command for xmpp module on asterisk.

Also small correction. I am using domain networklab.ca and all host tide to this domain name.

Node 1. Client connects and asterisk though xmpp module publish device state

2013-12-12 22:50:01.253 [pool-13-thread-6]  ClientConnectionManager.processSocketData()  FINEST: XMLNS set for packet: from=null, to=null, DATA=<iq xmlns="jabber:client" type="get" to="networklab.ca" from="betta@networklab.ca/nl-status02" id="aajvu"><ping xmlns="urn:xmpp:ping"/></iq>, SIZE=140, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=get from connection: c2s@xmpp01.networklab.ca/192.168.10.1_5222_192.168.10.2_43352
2013-12-12 22:50:01.253 [in_6-message-router]  MessageRouter.processPacket()  FINEST:   Processing packet: from=c2s@xmpp01.networklab.ca/192.168.10.1_5222_192.168.10.2_43352, to=sess-man@xmpp01.networklab.ca, DATA=<iq xmlns="jabber:client" type="get" to="networklab.ca" from="betta@networklab.ca/nl-status02" id="aajvu"><ping xmlns="urn:xmpp:ping"/></iq>, SIZE=140, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=get
2013-12-12 22:50:01.253 [in_6-message-router]  MessageRouter.getLocalComponent()  FINEST: Called for : networklab.ca
2013-12-12 22:50:01.254 [in_6-message-router]  MessageRouter.getLocalComponent()  FINEST: None compId matches: networklab.ca, for map: {stats@xmpp01.networklab.ca=tigase.stats.StatisticsCollector@552ee43b, sess-man@xmpp01.networklab.ca=tigase.cluster.SessionManagerClustered@7d9d1044, monitor@xmpp01.networklab.ca=tigase.cluster.MonitorClustered@a678505, cl-comp@xmpp01.networklab.ca=tigase.cluster.ClusterConnectionManager@6dffcd26, ws2s@xmpp01.networklab.ca=tigase.cluster.WebSocketClientConnectionClustered@4cbd23c8, bosh@xmpp01.networklab.ca=tigase.cluster.BoshConnectionClustered@47d052c3, c2s@xmpp01.networklab.ca=tigase.cluster.ClientConnectionClustered@7291ca34, s2s@xmpp01.networklab.ca=tigase.cluster.S2SConnectionClustered@e57bd52, amp@xmpp01.networklab.ca=tigase.server.amp.AmpComponent@2ae1ef17, muc@xmpp01.networklab.ca=tigase.muc.MUCComponent@3b897b54, basic-conf@xmpp01.networklab.ca=tigase.conf.Configurator@ded0b93, pubsub@xmpp01.networklab.ca=tigase.pubsub.PubSubComponent@7c5b6f4a, vhost-man@xmpp01.networklab.ca=tigase.vhosts.VHostManager@4592e709, cluster-contr@xmpp01.networklab.ca=tigase.cluster.ClusterController@7ad66ecc}
2013-12-12 22:50:01.254 [in_6-message-router]  MessageRouter.getLocalComponent()  FINEST: Still no comp name matches: networklab.ca, for map: {cl-comp=tigase.cluster.ClusterConnectionManager@6dffcd26, c2s=tigase.cluster.ClientConnectionClustered@7291ca34, basic-conf=tigase.conf.Configurator@ded0b93, s2s=tigase.cluster.S2SConnectionClustered@e57bd52, cluster-contr=tigase.cluster.ClusterController@7ad66ecc, bosh=tigase.cluster.BoshConnectionClustered@47d052c3, vhost-man=tigase.vhosts.VHostManager@4592e709, sess-man=tigase.cluster.SessionManagerClustered@7d9d1044, ws2s=tigase.cluster.WebSocketClientConnectionClustered@4cbd23c8, message-router=tigase.server.MessageRouter@2f7e238e, stats=tigase.stats.StatisticsCollector@552ee43b, pubsub=tigase.pubsub.PubSubComponent@7c5b6f4a, amp=tigase.server.amp.AmpComponent@2ae1ef17, monitor=tigase.cluster.MonitorClustered@a678505, muc=tigase.muc.MUCComponent@3b897b54}, for all VHosts: {3}
2013-12-12 22:50:01.254 [in_6-message-router]  MessageRouter.getLocalComponent()  FINEST: Called for : sess-man@xmpp01.networklab.ca
2013-12-12 22:50:01.254 [in_6-message-router]  MessageRouter.processPacket()  FINEST:   1. Packet will be processed by: sess-man@xmpp01.networklab.ca, from=c2s@xmpp01.networklab.ca/192.168.10.1_5222_192.168.10.2_43352, to=sess-man@xmpp01.networklab.ca, DATA=<iq xmlns="jabber:client" type="get" to="networklab.ca" from="betta@networklab.ca/nl-status02" id="aajvu"><ping xmlns="urn:xmpp:ping"/></iq>, SIZE=140, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=get
2013-12-12 22:50:01.254 [in_14-sess-man]   SessionManagerClustered.processPacket()  FINEST: Received packet: from=c2s@xmpp01.networklab.ca/192.168.10.1_5222_192.168.10.2_43352, to=sess-man@xmpp01.networklab.ca, DATA=<iq xmlns="jabber:client" type="get" to="networklab.ca" from="betta@networklab.ca/nl-status02" id="aajvu"><ping xmlns="urn:xmpp:ping"/></iq>, SIZE=140, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=get
2013-12-12 22:50:01.254 [in_14-sess-man]   SessionManagerClustered.processPacket()  FINEST: Ressource connection found: user_jid=betta@networklab.ca/nl-status02, packets=105, connectioId=c2s@xmpp01.networklab.ca/192.168.10.1_5222_192.168.10.2_43352, domain=networklab.ca, authState=AUTHORIZED, isAnon=false
2013-12-12 22:50:01.254 [in_14-sess-man]   DefaultClusteringStrategy.getNodesForPacketForward()  FINEST: Packet not suitable for forwarding: from=c2s@xmpp01.networklab.ca/192.168.10.1_5222_192.168.10.2_43352, to=sess-man@xmpp01.networklab.ca, DATA=<iq xmlns="jabber:client" type="get" to="networklab.ca" from="betta@networklab.ca/nl-status02" id="aajvu"><ping xmlns="urn:xmpp:ping"/></iq>, SIZE=140, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=get
2013-12-12 22:50:01.254 [in_14-sess-man]   DefaultClusteringStrategy.processPacket()  FINEST: No cluster nodes found for packet forward: from=c2s@xmpp01.networklab.ca/192.168.10.1_5222_192.168.10.2_43352, to=sess-man@xmpp01.networklab.ca, DATA=<iq xmlns="jabber:client" type="get" to="networklab.ca" from="betta@networklab.ca/nl-status02" id="aajvu"><ping xmlns="urn:xmpp:ping"/></iq>, SIZE=140, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=get
2013-12-12 22:50:01.254 [in_14-sess-man]   SessionManager.processPacket()     FINEST:   processing packet: from=c2s@xmpp01.networklab.ca/192.168.10.1_5222_192.168.10.2_43352, to=sess-man@xmpp01.networklab.ca, DATA=<iq xmlns="jabber:client" type="get" to="networklab.ca" from="betta@networklab.ca/nl-status02" id="aajvu"><ping xmlns="urn:xmpp:ping"/></iq>, SIZE=140, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=get, connection: user_jid=betta@networklab.ca/nl-status02, packets=105, connectioId=c2s@xmpp01.networklab.ca/192.168.10.1_5222_192.168.10.2_43352, domain=networklab.ca, authState=AUTHORIZED, isAnon=false
2013-12-12 22:50:01.254 [in_14-sess-man]   PacketDefaultHandler.preprocess()  FINEST:   Skipping setting correct from attribute: betta@networklab.ca/nl-status02, is already correct.
2013-12-12 22:50:01.254 [in_14-sess-man]   SessionManager.walk()              FINEST:   XMPPProcessorIfc: UrnXmppPing (urn:xmpp:ping)
 Request: from=c2s@xmpp01.networklab.ca/192.168.10.1_5222_192.168.10.2_43352, to=sess-man@xmpp01.networklab.ca, DATA=<iq xmlns="jabber:client" type="get" to="networklab.ca" from="betta@networklab.ca/nl-status02" id="aajvu"><ping xmlns="urn:xmpp:ping"/></iq>, SIZE=140, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=get, conn: user_jid=betta@networklab.ca/nl-status02, packets=106, connectioId=c2s@xmpp01.networklab.ca/192.168.10.1_5222_192.168.10.2_43352, domain=networklab.ca, authState=AUTHORIZED, isAnon=false
2013-12-12 22:50:01.255 [in_14-sess-man]   SessionManager.processPacket()     FINEST:   Packet processed by: [urn:xmpp:ping]
2013-12-12 22:50:01.255 [in_6-message-router]  MessageRouter.processPacket()  FINEST:   Processing packet: from=sess-man@xmpp01.networklab.ca, to=c2s@xmpp01.networklab.ca/192.168.10.1_5222_192.168.10.2_43352, DATA=<iq id="aajvu" type="result" to="betta@networklab.ca/nl-status02" from="networklab.ca" xmlns="jabber:client"/>, SIZE=110, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=result
2013-12-12 22:50:01.255 [in_6-message-router]  MessageRouter.getLocalComponent()  FINEST: Called for : betta@networklab.ca/nl-status02
2013-12-12 22:50:01.255 [in_6-message-router]  MessageRouter.getLocalComponent()  FINEST: None compId matches: betta@networklab.ca/nl-status02, for map: {stats@xmpp01.networklab.ca=tigase.stats.StatisticsCollector@552ee43b, sess-man@xmpp01.networklab.ca=tigase.cluster.SessionManagerClustered@7d9d1044, monitor@xmpp01.networklab.ca=tigase.cluster.MonitorClustered@a678505, cl-comp@xmpp01.networklab.ca=tigase.cluster.ClusterConnectionManager@6dffcd26, ws2s@xmpp01.networklab.ca=tigase.cluster.WebSocketClientConnectionClustered@4cbd23c8, bosh@xmpp01.networklab.ca=tigase.cluster.BoshConnectionClustered@47d052c3, c2s@xmpp01.networklab.ca=tigase.cluster.ClientConnectionClustered@7291ca34, s2s@xmpp01.networklab.ca=tigase.cluster.S2SConnectionClustered@e57bd52, amp@xmpp01.networklab.ca=tigase.server.amp.AmpComponent@2ae1ef17, muc@xmpp01.networklab.ca=tigase.muc.MUCComponent@3b897b54, basic-conf@xmpp01.networklab.ca=tigase.conf.Configurator@ded0b93, pubsub@xmpp01.networklab.ca=tigase.pubsub.PubSubComponent@7c5b6f4a, vhost-man@xmpp01.networklab.ca=tigase.vhosts.VHostManager@4592e709, cluster-contr@xmpp01.networklab.ca=tigase.cluster.ClusterController@7ad66ecc}
2013-12-12 22:50:01.255 [in_6-message-router]  MessageRouter.getLocalComponent()  FINEST: Still no comp name matches: betta@networklab.ca/nl-status02, for map: {cl-comp=tigase.cluster.ClusterConnectionManager@6dffcd26, c2s=tigase.cluster.ClientConnectionClustered@7291ca34, basic-conf=tigase.conf.Configurator@ded0b93, s2s=tigase.cluster.S2SConnectionClustered@e57bd52, cluster-contr=tigase.cluster.ClusterController@7ad66ecc, bosh=tigase.cluster.BoshConnectionClustered@47d052c3, vhost-man=tigase.vhosts.VHostManager@4592e709, sess-man=tigase.cluster.SessionManagerClustered@7d9d1044, ws2s=tigase.cluster.WebSocketClientConnectionClustered@4cbd23c8, message-router=tigase.server.MessageRouter@2f7e238e, stats=tigase.stats.StatisticsCollector@552ee43b, pubsub=tigase.pubsub.PubSubComponent@7c5b6f4a, amp=tigase.server.amp.AmpComponent@2ae1ef17, monitor=tigase.cluster.MonitorClustered@a678505, muc=tigase.muc.MUCComponent@3b897b54}, for all VHosts: {3}
2013-12-12 22:50:01.255 [in_6-message-router]  MessageRouter.getLocalComponent()  FINEST: Called for : c2s@xmpp01.networklab.ca/192.168.10.1_5222_192.168.10.2_43352
2013-12-12 22:50:01.255 [in_6-message-router]  MessageRouter.getLocalComponent()  FINEST: None compId matches: c2s@xmpp01.networklab.ca/192.168.10.1_5222_192.168.10.2_43352, for map: {stats@xmpp01.networklab.ca=tigase.stats.StatisticsCollector@552ee43b, sess-man@xmpp01.networklab.ca=tigase.cluster.SessionManagerClustered@7d9d1044, monitor@xmpp01.networklab.ca=tigase.cluster.MonitorClustered@a678505, cl-comp@xmpp01.networklab.ca=tigase.cluster.ClusterConnectionManager@6dffcd26, ws2s@xmpp01.networklab.ca=tigase.cluster.WebSocketClientConnectionClustered@4cbd23c8, bosh@xmpp01.networklab.ca=tigase.cluster.BoshConnectionClustered@47d052c3, c2s@xmpp01.networklab.ca=tigase.cluster.ClientConnectionClustered@7291ca34, s2s@xmpp01.networklab.ca=tigase.cluster.S2SConnectionClustered@e57bd52, amp@xmpp01.networklab.ca=tigase.server.amp.AmpComponent@2ae1ef17, muc@xmpp01.networklab.ca=tigase.muc.MUCComponent@3b897b54, basic-conf@xmpp01.networklab.ca=tigase.conf.Configurator@ded0b93, pubsub@xmpp01.networklab.ca=tigase.pubsub.PubSubComponent@7c5b6f4a, vhost-man@xmpp01.networklab.ca=tigase.vhosts.VHostManager@4592e709, cluster-contr@xmpp01.networklab.ca=tigase.cluster.ClusterController@7ad66ecc}
2013-12-12 22:50:01.255 [in_6-message-router]  MessageRouter.processPacket()  FINEST:   1. Packet will be processed by: c2s@xmpp01.networklab.ca, from=sess-man@xmpp01.networklab.ca, to=c2s@xmpp01.networklab.ca/192.168.10.1_5222_192.168.10.2_43352, DATA=<iq id="aajvu" type="result" to="betta@networklab.ca/nl-status02" from="networklab.ca" xmlns="jabber:client"/>, SIZE=110, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=result
2013-12-12 22:50:01.255 [in_6-c2s]         ClientConnectionManager.processPacket()  FINEST: Processing packet: from=sess-man@xmpp01.networklab.ca, to=c2s@xmpp01.networklab.ca/192.168.10.1_5222_192.168.10.2_43352, DATA=<iq id="aajvu" type="result" to="betta@networklab.ca/nl-status02" from="networklab.ca" xmlns="jabber:client"/>, SIZE=110, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=result
2013-12-12 22:50:01.256 [in_6-c2s]         ConnectionManager.writePacketToSocket()  FINEST: c2s@xmpp01.networklab.ca/192.168.10.1_5222_192.168.10.2_43352, type: accept, Socket: TLS: c2s@xmpp01.networklab.ca/192.168.10.1_5222_192.168.10.2_43352 Socket[addr=/192.168.10.2,port=43352,localport=5222], jid: betta@networklab.ca/nl-status02, Writing packet: from=sess-man@xmpp01.networklab.ca, to=c2s@xmpp01.networklab.ca/192.168.10.1_5222_192.168.10.2_43352, DATA=<iq id="aajvu" type="result" to="betta@networklab.ca/nl-status02" from="networklab.ca" xmlns="jabber:client"/>, SIZE=110, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=result
2013-12-12 22:50:02.000 [pool-8-thread-2]  ConnectionManager$1.run()          FINE:     Reconnecting service for component: s2s, to remote host: xmpp01.networklab.ca on port: 5,269
2013-12-12 22:50:02.002 [ConnectionOpenThread]  ConnectionManager$ConnectionListenerImpl.accept()  FINEST: Accept called for service: null@null
2013-12-12 22:50:02.002 [ConnectionOpenThread]  ConnectionManager.serviceStarted()  FINER: [[s2s]] Connection started: CID: null, null, type: accept, Socket: nullSocket[addr=/192.168.10.1,port=38110,localport=5269], jid: null
2013-12-12 22:50:02.002 [ConnectionOpenThread]  S2SConnectionManager.serviceStarted()  FINEST: s2s connection opened: CID: null, null, type: accept, Socket: nullSocket[addr=/192.168.10.1,port=38110,localport=5269], jid: null
2013-12-12 22:50:02.002 [ConnectionOpenThread]  ConnectionManager$ConnectionListenerImpl.accept()  FINEST: Accept called for service: networklab.ca@xmpp01.networklab.ca
2013-12-12 22:50:02.002 [ConnectionOpenThread]  ConnectionManager.serviceStarted()  FINER: [[s2s]] Connection started: CID: networklab.ca@xmpp01.networklab.ca, null, type: connect, Socket: nullSocket[addr=/192.168.10.1,port=5269,localport=38110], jid: null
2013-12-12 22:50:02.002 [ConnectionOpenThread]  S2SConnectionManager.serviceStarted()  FINEST: s2s connection opened: CID: networklab.ca@xmpp01.networklab.ca, null, type: connect, Socket: nullSocket[addr=/192.168.10.1,port=5269,localport=38110], jid: null
2013-12-12 22:50:02.002 [ConnectionOpenThread]  StreamOpen.serviceStarted()   FINEST:   CID: networklab.ca@xmpp01.networklab.ca, null, type: connect, Socket: nullSocket[addr=/192.168.10.1,port=5269,localport=38110], jid: null, sending: <stream:stream xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:server' xmlns:db='jabber:server:dialback' from='networklab.ca' to='xmpp01.networklab.ca' version='1.0'>
2013-12-12 22:50:02.003 [pool-13-thread-2]  S2SConnectionManager.xmppStreamOpened()  FINER: CID: null, null, type: accept, Socket: nullSocket[addr=/192.168.10.1,port=38110,localport=5269], jid: null, Stream opened: {to=xmpp01.networklab.ca, xmlns:stream=http://etherx.jabber.org/streams, from=networklab.ca, xmlns=jabber:server, xmlns:db=jabber:server:dialback, version=1.0}
2013-12-12 22:50:02.004 [pool-13-thread-2]  StreamFeatures.streamOpened()     FINEST:   CID: null, null, type: accept, Socket: nullSocket[addr=/192.168.10.1,port=38110,localport=5269], jid: null, Sending stream features: <stream:features><dialback xmlns="urn:xmpp:features:dialback"><required/></dialback><starttls xmlns="urn:ietf:params:xml:ns:xmpp-tls"/></stream:features>
2013-12-12 22:50:02.004 [pool-13-thread-2]  S2SAbstractProcessor.generateStreamError()  FINEST: Called from: 
java.lang.Throwable
    at tigase.server.xmppserver.proc.S2SAbstractProcessor.generateStreamError(S2SAbstractProcessor.java:146)
    at tigase.server.xmppserver.proc.StreamOpen.streamOpened(StreamOpen.java:268)
    at tigase.server.xmppserver.S2SConnectionManager.xmppStreamOpened(S2SConnectionManager.java:645)
    at tigase.server.xmppserver.S2SConnectionManager.xmppStreamOpened(S2SConnectionManager.java:71)
    at tigase.xmpp.XMPPIOService.xmppStreamOpened(XMPPIOService.java:756)
    at tigase.xmpp.XMPPDomBuilderHandler.startElement(XMPPDomBuilderHandler.java:315)
    at tigase.xml.SimpleParser.parse(SimpleParser.java:314)
    at tigase.xmpp.XMPPIOService.processSocketData(XMPPIOService.java:636)
    at tigase.net.IOService.call(IOService.java:262)
    at tigase.net.IOService.call(IOService.java:103)
    at java.util.concurrent.FutureTask.run(FutureTask.java:262)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
    at java.util.concurrent.FutureTask.run(FutureTask.java:262)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at java.lang.Thread.run(Thread.java:744)
2013-12-12 22:50:02.004 [pool-13-thread-2]  S2SAbstractProcessor.generateStreamError()  FINEST: CID: null, null, type: accept, Socket: nullSocket[addr=/192.168.10.1,port=38110,localport=5269], jid: null, Sending stream error: <stream:error><host-unknown xmlns='urn:ietf:params:xml:ns:xmpp-streams'/></stream:error></stream:stream>
2013-12-12 22:50:02.005 [pool-13-thread-2]  ConnectionManager.serviceStopped()  FINER:  [[s2s]] Connection stopped: CID: null, null, type: accept, Socket: nullSocket[unconnected], jid: null
2013-12-12 22:50:02.005 [pool-13-thread-2]  S2SConnectionManager.xmppStreamOpened()  FINER: CID: null, null, type: accept, Socket: nullSocket[unconnected], jid: null, Sending stream open: 
2013-12-12 22:50:02.005 [pool-13-thread-4]  S2SConnectionManager.xmppStreamClosed()  FINER: CID: networklab.ca@xmpp01.networklab.ca, null, type: connect, Socket: nullSocket[addr=/192.168.10.1,port=5269,localport=38110], jid: null, Stream closed.
2013-12-12 22:50:02.005 [pool-13-thread-4]  S2SConnectionManager.processSocketData()  FINEST: Processing socket data: from=null, to=null, DATA=<stream:error><host-unknown xmlns="urn:ietf:params:xml:ns:xmpp-streams"/></stream:error>, SIZE=88, XMLNS=null, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=null
2013-12-12 22:50:02.006 [pool-13-thread-4]  S2SAbstractProcessor.generateStreamError()  FINEST: Called from: 
java.lang.Throwable
    at tigase.server.xmppserver.proc.S2SAbstractProcessor.generateStreamError(S2SAbstractProcessor.java:146)
    at tigase.server.xmppserver.proc.PacketChecker.process(PacketChecker.java:116)
    at tigase.server.xmppserver.S2SConnectionManager.processSocketData(S2SConnectionManager.java:414)
    at tigase.server.xmppserver.S2SConnectionManager.processSocketData(S2SConnectionManager.java:71)
    at tigase.server.ConnectionManager.packetsReady(ConnectionManager.java:418)
    at tigase.server.ConnectionManager.packetsReady(ConnectionManager.java:81)
    at tigase.net.IOService.call(IOService.java:264)
    at tigase.net.IOService.call(IOService.java:103)
    at java.util.concurrent.FutureTask.run(FutureTask.java:262)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
    at java.util.concurrent.FutureTask.run(FutureTask.java:262)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at java.lang.Thread.run(Thread.java:744)
2013-12-12 22:50:02.006 [pool-13-thread-4]  S2SAbstractProcessor.generateStreamError()  FINEST: CID: networklab.ca@xmpp01.networklab.ca, null, type: connect, Socket: nullSocket[unconnected], jid: null, Sending stream error: <stream:error><improper-addressing xmlns='urn:ietf:params:xml:ns:xmpp-streams'/></stream:error></stream:stream>
2013-12-12 22:50:02.006 [pool-13-thread-4]  ConnectionManager.serviceStopped()  FINER:  [[s2s]] Connection stopped: CID: networklab.ca@xmpp01.networklab.ca, null, type: connect, Socket: nullSocket[unconnected], jid: null
2013-12-12 22:50:02.006 [pool-13-thread-4]  CIDConnections.checkOpenConnections()  FINEST: Scheduling task for openning a new connection for: networklab.ca@xmpp01.networklab.ca
2013-12-12 22:50:02.006 [pool-9-thread-2]  CIDConnections$2.run()             FINEST:   Running scheduled task for openning a new connection for: networklab.ca@xmpp01.networklab.ca
2013-12-12 22:50:02.006 [pool-9-thread-2]  CIDConnections.openOutgoingConnections()  FINEST: Checking DNS for host: xmpp01.networklab.ca for: networklab.ca@xmpp01.networklab.ca
2013-12-12 22:50:02.006 [pool-9-thread-2]  CIDConnections.initNewConnection()  FINEST:  STARTING new connection: networklab.ca@xmpp01.networklab.ca
2013-12-12 22:50:02.006 [pool-9-thread-2]  CIDConnections.initNewConnection()  FINEST:  networklab.ca@xmpp01.networklab.ca connection params: {cid=networklab.ca@xmpp01.networklab.ca, ifc=[Ljava.lang.String;@737ef1e, local-hostname=networklab.ca, port-no=5269, remote-hostname=xmpp01.networklab.ca, remote-ip=192.168.10.1, s2s-connection-key=S2S: null, socket=plain, srv-type=_xmpp-server._tcp, type=connect}
2013-12-12 22:50:02.007 [pool-9-thread-2]  ConnectionManager.reconnectService()  FINER: Reconnecting service for: s2s, scheduling next try in 2secs, cid: networklab.ca@xmpp01.networklab.ca

Second node in cluster getting the info

2013-12-13 04:50:16.972 [out_6-cl-comp]    DefaultClusteringStrategy.sendToNextNode()  FINEST: Called for packet: from=null, to=null, DATA=<presence xmlns="jabber:client" from="testuser1@networklab.ca/tigase-18" to="testuser2@networklab.ca"><priority>0</priority><c xmlns="http://jabber.org/protocol/caps" ver="Ds1p1IBtk9mgcwVH8c9UT+zzOcY=" hash="sha-1" node="http://counterpath.com/briavoip"/></presence>, SIZE=264, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, visitedNodes: [sess-man@xmpp01.networklab.ca, sess-man@xmpp02.networklab.ca], result: false
2013-12-13 04:50:17.007 [pool-13-thread-4]  ClusterConnectionManager.processSocketData()  FINEST: Processing socket data: from=null, to=null, DATA=<cluster xmlns="tigase:cluster" type="set" from="sess-man@xmpp01.networklab.ca" to="sess-man@xmpp02.networklab.ca" id="cl-345"><control><visited-nodes><node-id>sess-man@xmpp01.networklab.ca</node-id></visited-nodes><method-call name="packet-forward-sm-cmd"/><first-node>sess-man@xmpp01.networklab.ca</first-node></control><data><presence xmlns="jabber:client" type="probe" from="testuser1@networklab.ca" to="testuser2@networklab.ca"/></data></cluster>, SIZE=449, XMLNS=tigase:cluster, PRIORITY=CLUSTER, PERMISSION=NONE, TYPE=set
2013-12-13 04:50:17.007 [pool-13-thread-4]  ClusterElement.<init>()           FINEST:   Parsing cluster element: <cluster xmlns="tigase:cluster" type="set" from="sess-man@xmpp01.networklab.ca" to="sess-man@xmpp02.networklab.ca" id="cl-345"><control><visited-nodes><node-id>sess-man@xmpp01.networklab.ca</node-id></visited-nodes><method-call name="packet-forward-sm-cmd"/><first-node>sess-man@xmpp01.networklab.ca</first-node></control><data><presence xmlns="jabber:client" type="probe" from="testuser1@networklab.ca" to="testuser2@networklab.ca"/></data></cluster>
2013-12-13 04:50:17.007 [pool-13-thread-4]  ClusterElement.<init>()           FINEST:   First node found: sess-man@xmpp01.networklab.ca
2013-12-13 04:50:17.007 [pool-13-thread-4]  ClusterElement.<init>()           FINEST:   Found and added visited nodes: 1
2013-12-13 04:50:17.007 [pool-13-thread-4]  ClusterConnectionManager.processSocketData()  FINEST: Processing socket data: from=null, to=null, DATA=<cluster xmlns="tigase:cluster" type="set" from="sess-man@xmpp01.networklab.ca" to="sess-man@xmpp02.networklab.ca" id="cl-346"><control><visited-nodes><node-id>sess-man@xmpp01.networklab.ca</node-id></visited-nodes><method-call name="packet-forward-sm-cmd"/><first-node>sess-man@xmpp01.networklab.ca</first-node></control><data><presence xmlns="jabber:client" from="testuser1@networklab.ca/tigase-18" to="testuser2@networklab.ca"><priority>0</priority><c xmlns="http://jabber.org/protocol/caps" ver="Ds1p1IBtk9mgcwVH8c9UT+zzOcY=" hash="sha-1" node="http://counterpath.com/briavoip"/></presence></data></cluster>, SIZE=609, XMLNS=tigase:cluster, PRIORITY=CLUSTER, PERMISSION=NONE, TYPE=set
2013-12-13 04:50:17.008 [pool-13-thread-4]  ClusterElement.<init>()           FINEST:   Parsing cluster element: <cluster xmlns="tigase:cluster" type="set" from="sess-man@xmpp01.networklab.ca" to="sess-man@xmpp02.networklab.ca" id="cl-346"><control><visited-nodes><node-id>sess-man@xmpp01.networklab.ca</node-id></visited-nodes><method-call name="packet-forward-sm-cmd"/><first-node>sess-man@xmpp01.networklab.ca</first-node></control><data><presence xmlns="jabber:client" from="testuser1@networklab.ca/tigase-18" to="testuser2@networklab.ca"><priority>0</priority><c xmlns="http://jabber.org/protocol/caps" ver="Ds1p1IBtk9mgcwVH8c9UT+zzOcY=" hash="sha-1" node="http://counterpath.com/briavoip"/></presence></data></cluster>
2013-12-13 04:50:17.008 [pool-13-thread-4]  ClusterElement.<init>()           FINEST:   First node found: sess-man@xmpp01.networklab.ca
2013-12-13 04:50:17.008 [pool-13-thread-4]  ClusterElement.<init>()           FINEST:   Found and added visited nodes: 1
2013-12-13 04:50:17.008 [out_6-cl-comp]    ClusterElement.<init>()            FINEST:   Parsing cluster element: <cluster xmlns="tigase:cluster" type="set" from="sess-man@xmpp01.networklab.ca" to="sess-man@xmpp02.networklab.ca" id="cl-345"><control><visited-nodes><node-id>sess-man@xmpp01.networklab.ca</node-id></visited-nodes><method-call name="packet-forward-sm-cmd"/><first-node>sess-man@xmpp01.networklab.ca</first-node></control><data><presence xmlns="jabber:client" type="probe" from="testuser1@networklab.ca" to="testuser2@networklab.ca"/></data></cluster>
2013-12-13 04:50:17.008 [out_6-cl-comp]    ClusterElement.<init>()            FINEST:   First node found: sess-man@xmpp01.networklab.ca
2013-12-13 04:50:17.008 [out_6-cl-comp]    ClusterElement.<init>()            FINEST:   Found and added visited nodes: 1
2013-12-13 04:50:17.008 [out_6-cl-comp]    PacketForwardCmd.executeCommand()  FINEST:   Called fromNode: sess-man@xmpp01.networklab.ca, visitedNodes: [sess-man@xmpp01.networklab.ca, sess-man@xmpp02.networklab.ca], data: {}, packets: [<presence xmlns="jabber:client" type="probe" from="testuser1@networklab.ca" to="testuser2@networklab.ca"/>]
2013-12-13 04:50:17.008 [out_6-cl-comp]    SessionManager.getXMPPResourceConnection()  FINEST: Searching for resource connection for: testuser2@networklab.ca
2013-12-13 04:50:17.008 [out_6-cl-comp]    DefaultClusteringStrategy.sendToNextNode()  FINEST: Called for packet: from=null, to=null, DATA=<presence xmlns="jabber:client" type="probe" from="testuser1@networklab.ca" to="testuser2@networklab.ca"/>, SIZE=104, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=probe, visitedNodes: [sess-man@xmpp01.networklab.ca, sess-man@xmpp02.networklab.ca], result: false
2013-12-13 04:50:17.008 [out_6-cl-comp]    ClusterElement.<init>()            FINEST:   Parsing cluster element: <cluster xmlns="tigase:cluster" type="set" from="sess-man@xmpp01.networklab.ca" to="sess-man@xmpp02.networklab.ca" id="cl-346"><control><visited-nodes><node-id>sess-man@xmpp01.networklab.ca</node-id></visited-nodes><method-call name="packet-forward-sm-cmd"/><first-node>sess-man@xmpp01.networklab.ca</first-node></control><data><presence xmlns="jabber:client" from="testuser1@networklab.ca/tigase-18" to="testuser2@networklab.ca"><priority>0</priority><c xmlns="http://jabber.org/protocol/caps" ver="Ds1p1IBtk9mgcwVH8c9UT+zzOcY=" hash="sha-1" node="http://counterpath.com/briavoip"/></presence></data></cluster>
2013-12-13 04:50:17.009 [out_6-cl-comp]    ClusterElement.<init>()            FINEST:   First node found: sess-man@xmpp01.networklab.ca
2013-12-13 04:50:17.009 [out_6-cl-comp]    ClusterElement.<init>()            FINEST:   Found and added visited nodes: 1
2013-12-13 04:50:17.009 [out_6-cl-comp]    PacketForwardCmd.executeCommand()  FINEST:   Called fromNode: sess-man@xmpp01.networklab.ca, visitedNodes: [sess-man@xmpp01.networklab.ca, sess-man@xmpp02.networklab.ca], data: {}, packets: [<presence xmlns="jabber:client" from="testuser1@networklab.ca/tigase-18" to="testuser2@networklab.ca"><priority>0</priority><c xmlns="http://jabber.org/protocol/caps" ver="Ds1p1IBtk9mgcwVH8c9UT+zzOcY=" hash="sha-1" node="http://counterpath.com/briavoip"/></presence>]
2013-12-13 04:50:17.009 [out_6-cl-comp]    SessionManager.getXMPPResourceConnection()  FINEST: Searching for resource connection for: testuser2@networklab.ca
2013-12-13 04:50:17.009 [out_6-cl-comp]    DefaultClusteringStrategy.sendToNextNode()  FINEST: Called for packet: from=null, to=null, DATA=<presence xmlns="jabber:client" from="testuser1@networklab.ca/tigase-18" to="testuser2@networklab.ca"><priority>0</priority><c xmlns="http://jabber.org/protocol/caps" ver="Ds1p1IBtk9mgcwVH8c9UT+zzOcY=" hash="sha-1" node="http://counterpath.com/briavoip"/></presence>, SIZE=264, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, visitedNodes: [sess-man@xmpp01.networklab.ca, sess-man@xmpp02.networklab.ca], result: false
2013-12-13 04:50:17.028 [pool-13-thread-5]  ClusterConnectionManager.processSocketData()  FINEST: Processing socket data: from=null, to=null, DATA=<cluster xmlns="tigase:cluster" type="set" from="sess-man@xmpp01.networklab.ca" to="sess-man@xmpp02.networklab.ca" id="cl-347"><control><visited-nodes><node-id>sess-man@xmpp01.networklab.ca</node-id></visited-nodes><method-call name="packet-forward-sm-cmd"/><first-node>sess-man@xmpp01.networklab.ca</first-node></control><data><presence xmlns="jabber:client" type="probe" from="testuser1@networklab.ca" to="testuser3@networklab.ca"/></data></cluster>, SIZE=450, XMLNS=tigase:cluster, PRIORITY=CLUSTER, PERMISSION=NONE, TYPE=set
2013-12-13 04:50:17.028 [pool-13-thread-5]  ClusterElement.<init>()           FINEST:   Parsing cluster element: <cluster xmlns="tigase:cluster" type="set" from="sess-man@xmpp01.networklab.ca" to="sess-man@xmpp02.networklab.ca" id="cl-347"><control><visited-nodes><node-id>sess-man@xmpp01.networklab.ca</node-id></visited-nodes><method-call name="packet-forward-sm-cmd"/><first-node>sess-man@xmpp01.networklab.ca</first-node></control><data><presence xmlns="jabber:client" type="probe" from="testuser1@networklab.ca" to="testuser3@networklab.ca"/></data></cluster>
2013-12-13 04:50:17.028 [pool-13-thread-5]  ClusterElement.<init>()           FINEST:   First node found: sess-man@xmpp01.networklab.ca
2013-12-13 04:50:17.028 [pool-13-thread-5]  ClusterElement.<init>()           FINEST:   Found and added visited nodes: 1
2013-12-13 04:50:17.028 [pool-13-thread-5]  ClusterConnectionManager.processSocketData()  FINEST: Processing socket data: from=null, to=null, DATA=<cluster xmlns="tigase:cluster" type="set" from="sess-man@xmpp01.networklab.ca" to="sess-man@xmpp02.networklab.ca" id="cl-348"><control><visited-nodes><node-id>sess-man@xmpp01.networklab.ca</node-id></visited-nodes><method-call name="packet-forward-sm-cmd"/><first-node>sess-man@xmpp01.networklab.ca</first-node></control><data><presence xmlns="jabber:client" from="testuser1@networklab.ca/tigase-18" to="testuser3@networklab.ca"><priority>0</priority><c xmlns="http://jabber.org/protocol/caps" ver="Ds1p1IBtk9mgcwVH8c9UT+zzOcY=" hash="sha-1" node="http://counterpath.com/briavoip"/></presence></data></cluster>, SIZE=610, XMLNS=tigase:cluster, PRIORITY=CLUSTER, PERMISSION=NONE, TYPE=set
2013-12-13 04:50:17.028 [pool-13-thread-5]  ClusterElement.<init>()           FINEST:   Parsing cluster element: <cluster xmlns="tigase:cluster" type="set" from="sess-man@xmpp01.networklab.ca" to="sess-man@xmpp02.networklab.ca" id="cl-348"><control><visited-nodes><node-id>sess-man@xmpp01.networklab.ca</node-id></visited-nodes><method-call name="packet-forward-sm-cmd"/><first-node>sess-man@xmpp01.networklab.ca</first-node></control><data><presence xmlns="jabber:client" from="testuser1@networklab.ca/tigase-18" to="testuser3@networklab.ca"><priority>0</priority><c xmlns="http://jabber.org/protocol/caps" ver="Ds1p1IBtk9mgcwVH8c9UT+zzOcY=" hash="sha-1" node="http://counterpath.com/briavoip"/></presence></data></cluster>
2013-12-13 04:50:17.028 [pool-13-thread-5]  ClusterElement.<init>()           FINEST:   First node found: sess-man@xmpp01.networklab.ca
2013-12-13 04:50:17.028 [pool-13-thread-5]  ClusterElement.<init>()           FINEST:   Found and added visited nodes: 1
2013-12-13 04:50:17.029 [out_7-cl-comp]    ClusterElement.<init>()            FINEST:   Parsing cluster element: <cluster xmlns="tigase:cluster" type="set" from="sess-man@xmpp01.networklab.ca" to="sess-man@xmpp02.networklab.ca" id="cl-347"><control><visited-nodes><node-id>sess-man@xmpp01.networklab.ca</node-id></visited-nodes><method-call name="packet-forward-sm-cmd"/><first-node>sess-man@xmpp01.networklab.ca</first-node></control><data><presence xmlns="jabber:client" type="probe" from="testuser1@networklab.ca" to="testuser3@networklab.ca"/></data></cluster>
2013-12-13 04:50:17.029 [out_7-cl-comp]    ClusterElement.<init>()            FINEST:   First node found: sess-man@xmpp01.networklab.ca
2013-12-13 04:50:17.029 [out_7-cl-comp]    ClusterElement.<init>()            FINEST:   Found and added visited nodes: 1
2013-12-13 04:50:17.029 [out_7-cl-comp]    PacketForwardCmd.executeCommand()  FINEST:   Called fromNode: sess-man@xmpp01.networklab.ca, visitedNodes: [sess-man@xmpp01.networklab.ca, sess-man@xmpp02.networklab.ca], data: {}, packets: [<presence xmlns="jabber:client" type="probe" from="testuser1@networklab.ca" to="testuser3@networklab.ca"/>]
2013-12-13 04:50:17.029 [out_7-cl-comp]    SessionManager.getXMPPResourceConnection()  FINEST: Searching for resource connection for: testuser3@networklab.ca
2013-12-13 04:50:17.029 [out_7-cl-comp]    DefaultClusteringStrategy.sendToNextNode()  FINEST: Called for packet: from=null, to=null, DATA=<presence xmlns="jabber:client" type="probe" from="testuser1@networklab.ca" to="testuser3@networklab.ca"/>, SIZE=105, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=probe, visitedNodes: [sess-man@xmpp01.networklab.ca, sess-man@xmpp02.networklab.ca], result: false
2013-12-13 04:50:17.029 [out_7-cl-comp]    ClusterElement.<init>()            FINEST:   Parsing cluster element: <cluster xmlns="tigase:cluster" type="set" from="sess-man@xmpp01.networklab.ca" to="sess-man@xmpp02.networklab.ca" id="cl-348"><control><visited-nodes><node-id>sess-man@xmpp01.networklab.ca</node-id></visited-nodes><method-call name="packet-forward-sm-cmd"/><first-node>sess-man@xmpp01.networklab.ca</first-node></control><data><presence xmlns="jabber:client" from="testuser1@networklab.ca/tigase-18" to="testuser3@networklab.ca"><priority>0</priority><c xmlns="http://jabber.org/protocol/caps" ver="Ds1p1IBtk9mgcwVH8c9UT+zzOcY=" hash="sha-1" node="http://counterpath.com/briavoip"/></presence></data></cluster>
2013-12-13 04:50:17.029 [out_7-cl-comp]    ClusterElement.<init>()            FINEST:   First node found: sess-man@xmpp01.networklab.ca
2013-12-13 04:50:17.029 [out_7-cl-comp]    ClusterElement.<init>()            FINEST:   Found and added visited nodes: 1
2013-12-13 04:50:17.029 [out_7-cl-comp]    PacketForwardCmd.executeCommand()  FINEST:   Called fromNode: sess-man@xmpp01.networklab.ca, visitedNodes: [sess-man@xmpp01.networklab.ca, sess-man@xmpp02.networklab.ca], data: {}, packets: [<presence xmlns="jabber:client" from="testuser1@networklab.ca/tigase-18" to="testuser3@networklab.ca"><priority>0</priority><c xmlns="http://jabber.org/protocol/caps" ver="Ds1p1IBtk9mgcwVH8c9UT+zzOcY=" hash="sha-1" node="http://counterpath.com/briavoip"/></presence>]
2013-12-13 04:50:17.029 [out_7-cl-comp]    SessionManager.getXMPPResourceConnection()  FINEST: Searching for resource connection for: testuser3@networklab.ca
2013-12-13 04:50:17.030 [out_7-cl-comp]    DefaultClusteringStrategy.sendToNextNode()  FINEST: Called for packet: from=null, to=null, DATA=<presence xmlns="jabber:client" from="testuser1@networklab.ca/tigase-18" to="testuser3@networklab.ca"><priority>0</priority><c xmlns="http://jabber.org/protocol/caps" ver="Ds1p1IBtk9mgcwVH8c9UT+zzOcY=" hash="sha-1" node="http://counterpath.com/briavoip"/></presence>, SIZE=265, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, visitedNodes: [sess-man@xmpp01.networklab.ca, sess-man@xmpp02.networklab.ca], result: false
2013-12-13 04:50:17.097 [pool-13-thread-1]  ClusterConnectionManager.processSocketData()  FINEST: Processing socket data: from=null, to=null, DATA=<cluster xmlns="tigase:cluster" type="set" from="sess-man@xmpp01.networklab.ca" to="sess-man@xmpp02.networklab.ca" id="cl-351"><control><visited-nodes><node-id>sess-man@xmpp01.networklab.ca</node-id></visited-nodes><method-call name="packet-forward-sm-cmd"/><first-node>sess-man@xmpp01.networklab.ca</first-node></control><data><presence xmlns="jabber:client" from="testuser1@networklab.ca/tigase-18" to="testuser3@networklab.ca"><priority>0</priority><status>Available</status><c xmlns="http://jabber.org/protocol/caps" ver="7oXfSIxl9vrSpu0jI/zDhcWbxd0=" hash="sha-1" node="http://counterpath.com/briavoip"/></presence></data></cluster>, SIZE=636, XMLNS=tigase:cluster, PRIORITY=CLUSTER, PERMISSION=NONE, TYPE=set
2013-12-13 04:50:17.097 [pool-13-thread-1]  ClusterElement.<init>()           FINEST:   Parsing cluster element: <cluster xmlns="tigase:cluster" type="set" from="sess-man@xmpp01.networklab.ca" to="sess-man@xmpp02.networklab.ca" id="cl-351"><control><visited-nodes><node-id>sess-man@xmpp01.networklab.ca</node-id></visited-nodes><method-call name="packet-forward-sm-cmd"/><first-node>sess-man@xmpp01.networklab.ca</first-node></control><data><presence xmlns="jabber:client" from="testuser1@networklab.ca/tigase-18" to="testuser3@networklab.ca"><priority>0</priority><status>Available</status><c xmlns="http://jabber.org/protocol/caps" ver="7oXfSIxl9vrSpu0jI/zDhcWbxd0=" hash="sha-1" node="http://counterpath.com/briavoip"/></presence></data></cluster>
2013-12-13 04:50:17.098 [pool-13-thread-1]  ClusterElement.<init>()           FINEST:   First node found: sess-man@xmpp01.networklab.ca
2013-12-13 04:50:17.098 [pool-13-thread-1]  ClusterElement.<init>()           FINEST:   Found and added visited nodes: 1
2013-12-13 04:50:17.098 [pool-13-thread-1]  ClusterConnectionManager.processSocketData()  FINEST: Processing socket data: from=null, to=null, DATA=<cluster xmlns="tigase:cluster" type="set" from="sess-man@xmpp01.networklab.ca" to="sess-man@xmpp02.networklab.ca" id="cl-352"><control><visited-nodes><node-id>sess-man@xmpp01.networklab.ca</node-id></visited-nodes><method-call name="packet-forward-sm-cmd"/><first-node>sess-man@xmpp01.networklab.ca</first-node></control><data><presence xmlns="jabber:client" from="testuser1@networklab.ca/tigase-18" to="testuser3@networklab.ca"><priority>0</priority><status>Available</status><c xmlns="http://jabber.org/protocol/caps" ver="7oXfSIxl9vrSpu0jI/zDhcWbxd0=" hash="sha-1" node="http://counterpath.com/briavoip"/></presence></data></cluster>, SIZE=636, XMLNS=tigase:cluster, PRIORITY=CLUSTER, PERMISSION=NONE, TYPE=set
2013-12-13 04:50:17.098 [pool-13-thread-1]  ClusterElement.<init>()           FINEST:   Parsing cluster element: <cluster xmlns="tigase:cluster" type="set" from="sess-man@xmpp01.networklab.ca" to="sess-man@xmpp02.networklab.ca" id="cl-352"><control><visited-nodes><node-id>sess-man@xmpp01.networklab.ca</node-id></visited-nodes><method-call name="packet-forward-sm-cmd"/><first-node>sess-man@xmpp01.networklab.ca</first-node></control><data><presence xmlns="jabber:client" from="testuser1@networklab.ca/tigase-18" to="testuser3@networklab.ca"><priority>0</priority><status>Available</status><c xmlns="http://jabber.org/protocol/caps" ver="7oXfSIxl9vrSpu0jI/zDhcWbxd0=" hash="sha-1" node="http://counterpath.com/briavoip"/></presence></data></cluster>
2013-12-13 04:50:17.098 [pool-13-thread-1]  ClusterElement.<init>()           FINEST:   First node found: sess-man@xmpp01.networklab.ca
2013-12-13 04:50:17.098 [pool-13-thread-1]  ClusterElement.<init>()           FINEST:   Found and added visited nodes: 1
2013-12-13 04:50:17.098 [out_7-cl-comp]    ClusterElement.<init>()            FINEST:   Parsing cluster element: <cluster xmlns="tigase:cluster" type="set" from="sess-man@xmpp01.networklab.ca" to="sess-man@xmpp02.networklab.ca" id="cl-351"><control><visited-nodes><node-id>sess-man@xmpp01.networklab.ca</node-id></visited-nodes><method-call name="packet-forward-sm-cmd"/><first-node>sess-man@xmpp01.networklab.ca</first-node></control><data><presence xmlns="jabber:client" from="testuser1@networklab.ca/tigase-18" to="testuser3@networklab.ca"><priority>0</priority><status>Available</status><c xmlns="http://jabber.org/protocol/caps" ver="7oXfSIxl9vrSpu0jI/zDhcWbxd0=" hash="sha-1" node="http://counterpath.com/briavoip"/></presence></data></cluster>
2013-12-13 04:50:17.098 [out_7-cl-comp]    ClusterElement.<init>()            FINEST:   First node found: sess-man@xmpp01.networklab.ca
2013-12-13 04:50:17.098 [out_7-cl-comp]    ClusterElement.<init>()            FINEST:   Found and added visited nodes: 1
2013-12-13 04:50:17.098 [out_7-cl-comp]    PacketForwardCmd.executeCommand()  FINEST:   Called fromNode: sess-man@xmpp01.networklab.ca, visitedNodes: [sess-man@xmpp01.networklab.ca, sess-man@xmpp02.networklab.ca], data: {}, packets: [<presence xmlns="jabber:client" from="testuser1@networklab.ca/tigase-18" to="testuser3@networklab.ca"><priority>0</priority><status>Available</status><c xmlns="http://jabber.org/protocol/caps" ver="7oXfSIxl9vrSpu0jI/zDhcWbxd0=" hash="sha-1" node="http://counterpath.com/briavoip"/></presence>]
2013-12-13 04:50:17.099 [out_7-cl-comp]    SessionManager.getXMPPResourceConnection()  FINEST: Searching for resource connection for: testuser3@networklab.ca
2013-12-13 04:50:17.099 [out_7-cl-comp]    DefaultClusteringStrategy.sendToNextNode()  FINEST: Called for packet: from=null, to=null, DATA=<presence xmlns="jabber:client" from="testuser1@networklab.ca/tigase-18" to="testuser3@networklab.ca"><priority>0</priority><status>Available</status><c xmlns="http://jabber.org/protocol/caps" ver="7oXfSIxl9vrSpu0jI/zDhcWbxd0=" hash="sha-1" node="http://counterpath.com/briavoip"/></presence>, SIZE=291, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, visitedNodes: [sess-man@xmpp01.networklab.ca, sess-man@xmpp02.networklab.ca], result: false
2013-12-13 04:50:17.099 [out_7-cl-comp]    ClusterElement.<init>()            FINEST:   Parsing cluster element: <cluster xmlns="tigase:cluster" type="set" from="sess-man@xmpp01.networklab.ca" to="sess-man@xmpp02.networklab.ca" id="cl-352"><control><visited-nodes><node-id>sess-man@xmpp01.networklab.ca</node-id></visited-nodes><method-call name="packet-forward-sm-cmd"/><first-node>sess-man@xmpp01.networklab.ca</first-node></control><data><presence xmlns="jabber:client" from="testuser1@networklab.ca/tigase-18" to="testuser3@networklab.ca"><priority>0</priority><status>Available</status><c xmlns="http://jabber.org/protocol/caps" ver="7oXfSIxl9vrSpu0jI/zDhcWbxd0=" hash="sha-1" node="http://counterpath.com/briavoip"/></presence></data></cluster>
2013-12-13 04:50:17.099 [out_7-cl-comp]    ClusterElement.<init>()            FINEST:   First node found: sess-man@xmpp01.networklab.ca
2013-12-13 04:50:17.099 [out_7-cl-comp]    ClusterElement.<init>()            FINEST:   Found and added visited nodes: 1
2013-12-13 04:50:17.099 [out_7-cl-comp]    PacketForwardCmd.executeCommand()  FINEST:   Called fromNode: sess-man@xmpp01.networklab.ca, visitedNodes: [sess-man@xmpp01.networklab.ca, sess-man@xmpp02.networklab.ca], data: {}, packets: [<presence xmlns="jabber:client" from="testuser1@networklab.ca/tigase-18" to="testuser3@networklab.ca"><priority>0</priority><status>Available</status><c xmlns="http://jabber.org/protocol/caps" ver="7oXfSIxl9vrSpu0jI/zDhcWbxd0=" hash="sha-1" node="http://counterpath.com/briavoip"/></presence>]
2013-12-13 04:50:17.099 [out_7-cl-comp]    SessionManager.getXMPPResourceConnection()  FINEST: Searching for resource connection for: testuser3@networklab.ca
2013-12-13 04:50:17.099 [out_7-cl-comp]    DefaultClusteringStrategy.sendToNextNode()  FINEST: Called for packet: from=null, to=null, DATA=<presence xmlns="jabber:client" from="testuser1@networklab.ca/tigase-18" to="testuser3@networklab.ca"><priority>0</priority><status>Available</status><c xmlns="http://jabber.org/protocol/caps" ver="7oXfSIxl9vrSpu0jI/zDhcWbxd0=" hash="sha-1" node="http://counterpath.com/briavoip"/></presence>, SIZE=291, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, visitedNodes: [sess-man@xmpp01.networklab.ca, sess-man@xmpp02.networklab.ca], result: false
2013-12-13 04:50:17.140 [pool-13-thread-3]  ClusterConnectionManager.processSocketData()  FINEST: Processing socket data: from=null, to=null, DATA=<cluster xmlns="tigase:cluster" type="set" from="sess-man@xmpp01.networklab.ca" to="sess-man@xmpp02.networklab.ca" id="cl-349"><control><visited-nodes><node-id>sess-man@xmpp01.networklab.ca</node-id></visited-nodes><method-call name="packet-forward-sm-cmd"><par name="user-session-found-key">sess-man@xmpp01.networklab.ca</par></method-call><first-node>sess-man@xmpp01.networklab.ca</first-node></control><data><iq xmlns="jabber:client" type="result" from="testuser1@networklab.ca/tigase-18" to="testuser1@networklab.ca/tigase-18"/></data></cluster>, SIZE=551, XMLNS=tigase:cluster, PRIORITY=CLUSTER, PERMISSION=NONE, TYPE=set
2013-12-13 04:50:17.147 [pool-13-thread-3]  ClusterElement.<init>()           FINEST:   Parsing cluster element: <cluster xmlns="tigase:cluster" type="set" from="sess-man@xmpp01.networklab.ca" to="sess-man@xmpp02.networklab.ca" id="cl-349"><control><visited-nodes><node-id>sess-man@xmpp01.networklab.ca</node-id></visited-nodes><method-call name="packet-forward-sm-cmd"><par name="user-session-found-key">sess-man@xmpp01.networklab.ca</par></method-call><first-node>sess-man@xmpp01.networklab.ca</first-node></control><data><iq xmlns="jabber:client" type="result" from="testuser1@networklab.ca/tigase-18" to="testuser1@networklab.ca/tigase-18"/></data></cluster>
2013-12-13 04:50:17.148 [pool-13-thread-3]  ClusterElement.<init>()           FINEST:   First node found: sess-man@xmpp01.networklab.ca
2013-12-13 04:50:17.148 [pool-13-thread-3]  ClusterElement.<init>()           FINEST:   Found and added visited nodes: 1
2013-12-13 04:50:17.148 [out_1-cl-comp]    ClusterElement.<init>()            FINEST:   Parsing cluster element: <cluster xmlns="tigase:cluster" type="set" from="sess-man@xmpp01.networklab.ca" to="sess-man@xmpp02.networklab.ca" id="cl-349"><control><visited-nodes><node-id>sess-man@xmpp01.networklab.ca</node-id></visited-nodes><method-call name="packet-forward-sm-cmd"><par name="user-session-found-key">sess-man@xmpp01.networklab.ca</par></method-call><first-node>sess-man@xmpp01.networklab.ca</first-node></control><data><iq xmlns="jabber:client" type="result" from="testuser1@networklab.ca/tigase-18" to="testuser1@networklab.ca/tigase-18"/></data></cluster>
2013-12-13 04:50:17.148 [out_1-cl-comp]    ClusterElement.<init>()            FINEST:   First node found: sess-man@xmpp01.networklab.ca
2013-12-13 04:50:17.148 [out_1-cl-comp]    ClusterElement.<init>()            FINEST:   Found and added visited nodes: 1
2013-12-13 04:50:17.148 [out_1-cl-comp]    PacketForwardCmd.executeCommand()  FINEST:   Called fromNode: sess-man@xmpp01.networklab.ca, visitedNodes: [sess-man@xmpp01.networklab.ca, sess-man@xmpp02.networklab.ca], data: {user-session-found-key=sess-man@xmpp01.networklab.ca}, packets: [<iq xmlns="jabber:client" type="result" from="testuser1@networklab.ca/tigase-18" to="testuser1@networklab.ca/tigase-18"/>]
2013-12-13 04:50:17.148 [out_1-cl-comp]    SessionManager.getXMPPResourceConnection()  FINEST: Searching for resource connection for: testuser1@networklab.ca/tigase-18
2013-12-13 04:50:17.148 [out_1-cl-comp]    DefaultClusteringStrategy.sendToNextNode()  FINEST: Called for packet: from=null, to=null, DATA=<iq xmlns="jabber:client" type="result" from="testuser1@networklab.ca/tigase-18" to="testuser1@networklab.ca/tigase-18"/>, SIZE=123, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=result, visitedNodes: [sess-man@xmpp01.networklab.ca, sess-man@xmpp02.networklab.ca], result: false
2013-12-13 04:50:17.151 [pool-13-thread-2]  ClusterConnectionManager.processSocketData()  FINEST: Processing socket data: from=null, to=null, DATA=<cluster xmlns="tigase:cluster" type="set" from="sess-man@xmpp01.networklab.ca" to="sess-man@xmpp02.networklab.ca" id="cl-350"><control><visited-nodes><node-id>sess-man@xmpp01.networklab.ca</node-id></visited-nodes><method-call name="packet-forward-sm-cmd"/><first-node>sess-man@xmpp01.networklab.ca</first-node></control><data><presence xmlns="jabber:client" from="testuser1@networklab.ca/tigase-18" to="testuser2@networklab.ca"><priority>0</priority><status>Available</status><c xmlns="http://jabber.org/protocol/caps" ver="7oXfSIxl9vrSpu0jI/zDhcWbxd0=" hash="sha-1" node="http://counterpath.com/briavoip"/></presence></data></cluster>, SIZE=635, XMLNS=tigase:cluster, PRIORITY=CLUSTER, PERMISSION=NONE, TYPE=set
2013-12-13 04:50:17.151 [pool-13-thread-2]  ClusterElement.<init>()           FINEST:   Parsing cluster element: <cluster xmlns="tigase:cluster" type="set" from="sess-man@xmpp01.networklab.ca" to="sess-man@xmpp02.networklab.ca" id="cl-350"><control><visited-nodes><node-id>sess-man@xmpp01.networklab.ca</node-id></visited-nodes><method-call name="packet-forward-sm-cmd"/><first-node>sess-man@xmpp01.networklab.ca</first-node></control><data><presence xmlns="jabber:client" from="testuser1@networklab.ca/tigase-18" to="testuser2@networklab.ca"><priority>0</priority><status>Available</status><c xmlns="http://jabber.org/protocol/caps" ver="7oXfSIxl9vrSpu0jI/zDhcWbxd0=" hash="sha-1" node="http://counterpath.com/briavoip"/></presence></data></cluster>
2013-12-13 04:50:17.151 [pool-13-thread-2]  ClusterElement.<init>()           FINEST:   First node found: sess-man@xmpp01.networklab.ca
2013-12-13 04:50:17.152 [pool-13-thread-2]  ClusterElement.<init>()           FINEST:   Found and added visited nodes: 1
2013-12-13 04:50:17.152 [pool-13-thread-2]  ClusterConnectionManager.processSocketData()  FINEST: Processing socket data: from=null, to=null, DATA=<cluster xmlns="tigase:cluster" type="set" from="sess-man@xmpp01.networklab.ca" to="sess-man@xmpp02.networklab.ca" id="cl-353"><control><visited-nodes><node-id>sess-man@xmpp01.networklab.ca</node-id></visited-nodes><method-call name="packet-forward-sm-cmd"/><first-node>sess-man@xmpp01.networklab.ca</first-node></control><data><presence xmlns="jabber:client" from="testuser1@networklab.ca/tigase-18" to="testuser2@networklab.ca"><priority>0</priority><status>Available</status><c xmlns="http://jabber.org/protocol/caps" ver="7oXfSIxl9vrSpu0jI/zDhcWbxd0=" hash="sha-1" node="http://counterpath.com/briavoip"/></presence></data></cluster>, SIZE=635, XMLNS=tigase:cluster, PRIORITY=CLUSTER, PERMISSION=NONE, TYPE=set
2013-12-13 04:50:17.152 [pool-13-thread-2]  ClusterElement.<init>()           FINEST:   Parsing cluster element: <cluster xmlns="tigase:cluster" type="set" from="sess-man@xmpp01.networklab.ca" to="sess-man@xmpp02.networklab.ca" id="cl-353"><control><visited-nodes><node-id>sess-man@xmpp01.networklab.ca</node-id></visited-nodes><method-call name="packet-forward-sm-cmd"/><first-node>sess-man@xmpp01.networklab.ca</first-node></control><data><presence xmlns="jabber:client" from="testuser1@networklab.ca/tigase-18" to="testuser2@networklab.ca"><priority>0</priority><status>Available</status><c xmlns="http://jabber.org/protocol/caps" ver="7oXfSIxl9vrSpu0jI/zDhcWbxd0=" hash="sha-1" node="http://counterpath.com/briavoip"/></presence></data></cluster>
2013-12-13 04:50:17.152 [pool-13-thread-2]  ClusterElement.<init>()           FINEST:   First node found: sess-man@xmpp01.networklab.ca
2013-12-13 04:50:17.152 [pool-13-thread-2]  ClusterElement.<init>()           FINEST:   Found and added visited nodes: 1
2013-12-13 04:50:17.152 [out_6-cl-comp]    ClusterElement.<init>()            FINEST:   Parsing cluster element: <cluster xmlns="tigase:cluster" type="set" from="sess-man@xmpp01.networklab.ca" to="sess-man@xmpp02.networklab.ca" id="cl-350"><control><visited-nodes><node-id>sess-man@xmpp01.networklab.ca</node-id></visited-nodes><method-call name="packet-forward-sm-cmd"/><first-node>sess-man@xmpp01.networklab.ca</first-node></control><data><presence xmlns="jabber:client" from="testuser1@networklab.ca/tigase-18" to="testuser2@networklab.ca"><priority>0</priority><status>Available</status><c xmlns="http://jabber.org/protocol/caps" ver="7oXfSIxl9vrSpu0jI/zDhcWbxd0=" hash="sha-1" node="http://counterpath.com/briavoip"/></presence></data></cluster>
2013-12-13 04:50:17.152 [out_6-cl-comp]    ClusterElement.<init>()            FINEST:   First node found: sess-man@xmpp01.networklab.ca
2013-12-13 04:50:17.152 [out_6-cl-comp]    ClusterElement.<init>()            FINEST:   Found and added visited nodes: 1
2013-12-13 04:50:17.152 [out_6-cl-comp]    PacketForwardCmd.executeCommand()  FINEST:   Called fromNode: sess-man@xmpp01.networklab.ca, visitedNodes: [sess-man@xmpp01.networklab.ca, sess-man@xmpp02.networklab.ca], data: {}, packets: [<presence xmlns="jabber:client" from="testuser1@networklab.ca/tigase-18" to="testuser2@networklab.ca"><priority>0</priority><status>Available</status><c xmlns="http://jabber.org/protocol/caps" ver="7oXfSIxl9vrSpu0jI/zDhcWbxd0=" hash="sha-1" node="http://counterpath.com/briavoip"/></presence>]
2013-12-13 04:50:17.153 [out_6-cl-comp]    SessionManager.getXMPPResourceConnection()  FINEST: Searching for resource connection for: testuser2@networklab.ca
2013-12-13 04:50:17.153 [out_6-cl-comp]    DefaultClusteringStrategy.sendToNextNode()  FINEST: Called for packet: from=null, to=null, DATA=<presence xmlns="jabber:client" from="testuser1@networklab.ca/tigase-18" to="testuser2@networklab.ca"><priority>0</priority><status>Available</status><c xmlns="http://jabber.org/protocol/caps" ver="7oXfSIxl9vrSpu0jI/zDhcWbxd0=" hash="sha-1" node="http://counterpath.com/briavoip"/></presence>, SIZE=290, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, visitedNodes: [sess-man@xmpp01.networklab.ca, sess-man@xmpp02.networklab.ca], result: false
2013-12-13 04:50:17.153 [out_6-cl-comp]    ClusterElement.<init>()            FINEST:   Parsing cluster element: <cluster xmlns="tigase:cluster" type="set" from="sess-man@xmpp01.networklab.ca" to="sess-man@xmpp02.networklab.ca" id="cl-353"><control><visited-nodes><node-id>sess-man@xmpp01.networklab.ca</node-id></visited-nodes><method-call name="packet-forward-sm-cmd"/><first-node>sess-man@xmpp01.networklab.ca</first-node></control><data><presence xmlns="jabber:client" from="testuser1@networklab.ca/tigase-18" to="testuser2@networklab.ca"><priority>0</priority><status>Available</status><c xmlns="http://jabber.org/protocol/caps" ver="7oXfSIxl9vrSpu0jI/zDhcWbxd0=" hash="sha-1" node="http://counterpath.com/briavoip"/></presence></data></cluster>
2013-12-13 04:50:17.153 [out_6-cl-comp]    ClusterElement.<init>()            FINEST:   First node found: sess-man@xmpp01.networklab.ca
2013-12-13 04:50:17.153 [out_6-cl-comp]    ClusterElement.<init>()            FINEST:   Found and added visited nodes: 1
2013-12-13 04:50:17.153 [out_6-cl-comp]    PacketForwardCmd.executeCommand()  FINEST:   Called fromNode: sess-man@xmpp01.networklab.ca, visitedNodes: [sess-man@xmpp01.networklab.ca, sess-man@xmpp02.networklab.ca], data: {}, packets: [<presence xmlns="jabber:client" from="testuser1@networklab.ca/tigase-18" to="testuser2@networklab.ca"><priority>0</priority><status>Available</status><c xmlns="http://jabber.org/protocol/caps" ver="7oXfSIxl9vrSpu0jI/zDhcWbxd0=" hash="sha-1" node="http://counterpath.com/briavoip"/></presence>]
2013-12-13 04:50:17.153 [out_6-cl-comp]    SessionManager.getXMPPResourceConnection()  FINEST: Searching for resource connection for: testuser2@networklab.ca
2013-12-13 04:50:17.153 [out_6-cl-comp]    DefaultClusteringStrategy.sendToNextNode()  FINEST: Called for packet: from=null, to=null, DATA=<presence xmlns="jabber:client" from="testuser1@networklab.ca/tigase-18" to="testuser2@networklab.ca"><priority>0</priority><status>Available</status><c xmlns="http://jabber.org/protocol/caps" ver="7oXfSIxl9vrSpu0jI/zDhcWbxd0=" hash="sha-1" node="http://counterpath.com/briavoip"/></presence>, SIZE=290, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, visitedNodes: [sess-man@xmpp01.networklab.ca, sess-man@xmpp02.networklab.ca], result: false
2013-12-13 04:50:35.640 [hostnames]        UserRepoRepository.reload()        CONFIG:   All loaded items: {networklab.ca=Domain: networklab.ca, enabled: true, anonym: false, register: true, maxusers: 150, tls: true, s2sSecret: null, domainFilter: ALL}
2013-12-13 04:51:35.640 [hostnames]        UserRepoRepository.reload()        CONFIG:   All loaded items: {networklab.ca=Domain: networklab.ca, enabled: true, anonym: false, register: true, maxusers: 150, tls: true, s2sSecret: null, domainFilter: ALL}
2013-12-13 04:52:35.640 [hostnames]        UserRepoRepository.reload()        CONFIG:   All loaded items: {networklab.ca=Domain: networklab.ca, enabled: true, anonym: false, register: true, maxusers: 150, tls: true, s2sSecret: null, domainFilter: ALL}
2013-12-13 04:53:35.640 [hostnames]        UserRepoRepository.reload()        CONFIG:   All loaded items: {networklab.ca=Domain: networklab.ca, enabled: true, anonym: false, register: true, maxusers: 150, tls: true, s2sSecret: null, domainFilter: ALL}
2013-12-13 04:54:35.640 [hostnames]        UserRepoRepository.reload()        CONFIG:   All loaded items: {networklab.ca=Domain: networklab.ca, enabled: true, anonym: false, register: true, maxusers: 150, tls: true, s2sSecret: null, domainFilter: ALL}
2013-12-13 04:55:35.640 [hostnames]        UserRepoRepository.reload()        CONFIG:   All loaded items: {networklab.ca=Domain: networklab.ca, enabled: true, anonym: false, register: true, maxusers: 150, tls: true, s2sSecret: null, domainFilter: ALL}
2013-12-13 04:56:35.640 [hostnames]        UserRepoRepository.reload()        CONFIG:   All loaded items: {networklab.ca=Domain: networklab.ca, enabled: true, anonym: false, register: true, maxusers: 150, tls: true, s2sSecret: null, domainFilter: ALL}
2013-12-13 04:57:35.640 [hostnames]        UserRepoRepository.reload()        CONFIG:   All loaded items: {networklab.ca=Domain: networklab.ca, enabled: true, anonym: false, register: true, maxusers: 150, tls: true, s2sSecret: null, domainFilter: ALL}
2013-12-13 04:58:35.640 [hostnames]        UserRepoRepository.reload()        CONFIG:   All loaded items: {networklab.ca=Domain: networklab.ca, enabled: true, anonym: false, register: true, maxusers: 150, tls: true, s2sSecret: null, domainFilter: ALL}
2013-12-13 04:59:27.346 [stats-cache]      S2SConnectionManager.getStatistics()  FINEST: CID: networklab.ca@proxy.eu.jabber.org, OUT: 0, OUT_HAND: 0, IN: 0, dbKeys: 0, waiting: 0, waiting_control: 0
2013-12-13 04:59:27.347 [stats-cache]      S2SConnectionManager.getStatistics()  FINEST: CID: networklab.ca@xmpp02.networklab.ca, OUT: 0, OUT_HAND: 0, IN: 0, dbKeys: 0, waiting: 0, waiting_control: 0
2013-12-13 04:59:27.347 [stats-cache]      S2SConnectionManager.getStatistics()  FINEST: CID: networklab.ca@proxy.networklab.ca, OUT: 0, OUT_HAND: 0, IN: 0, dbKeys: 0, waiting: 0, waiting_control: 0
2013-12-13 04:59:35.640 [hostnames]        UserRepoRepository.reload()        CONFIG:   All loaded items: {networklab.ca=Domain: networklab.ca, enabled: true, anonym: false, register: true, maxusers: 150, tls: true, s2sSecret: null, domainFilter: ALL}
2013-12-13 05:00:35.641 [hostnames]        UserRepoRepository.reload()        CONFIG:   All loaded items: {networklab.ca=Domain: networklab.ca, enabled: true, anonym: false, register: true, maxusers: 150, tls: true, s2sSecret: null, domainFilter: ALL}
2013-12-13 05:01:35.641 [hostnames]        UserRepoRepository.reload()        CONFIG:   All loaded items: {networklab.ca=Domain: networklab.ca, enabled: true, anonym: false, register: true, maxusers: 150, tls: true, s2sSecret: null, domainFilter: ALL}
2013-12-13 05:02:35.641 [hostnames]        UserRepoRepository.reload()        CONFIG:   All loaded items: {networklab.ca=Domain: networklab.ca, enabled: true, anonym: false, register: true, maxusers: 150, tls: true, s2sSecret: null, domainFilter: ALL}
2013-12-13 05:03:35.640 [hostnames]        UserRepoRepository.reload()        CONFIG:   All loaded items: {networklab.ca=Domain: networklab.ca, enabled: true, anonym: false, register: true, maxusers: 150, tls: true, s2sSecret: null, domainFilter: ALL}
2013-12-13 05:04:35.640 [hostnames]        UserRepoRepository.reload()        CONFIG:   All loaded items: {networklab.ca=Domain: networklab.ca, enabled: true, anonym: false, register: true, maxusers: 150, tls: true, s2sSecret: null, domainFilter: ALL}

Added by Wojciech Kapcia TigaseTeam over 5 years ago

How does your asterisk config look now? Do you, by any chance used @xmpp01.networklab.ca@?

In the mentioned logs there is no exception regarding pubsub. The S2S Exception stems from a fact, that the server tries to connect to xmpp01.networklab.ca address, this may happen if, for example, user has a contact with such domain name in the roster, or you perform a query for that domain - basically this is not a VHost configured to handle by Tigase thus a connection attempt to this 'remote host' is made (resolving to local one of course) but the connection fails with the stream error "host-unknown" (because it's not configured, and you rather should avoid to use such name).

As for VirtualComponent and PubSub - currently PubSub doesn't support clustering thus, if you want to use you you have two choices - either use VirtualComponent or ExternalComponent.

Added by Slava Bendersky over 5 years ago

this asterisk config

[root@xmpp01 ~]# cat /etc/asterisk/xmpp_custom.conf 
[asterisk]
type=client
serverhost=xmpp01.networklab.ca
pubsub_node=xmpp01.networklab.ca
username=delta@networklab.ca/nl-status01
secret=
distribute_events=yes
usetls=yes
usesasl=yes
status=available
buddy=betta@networklab.ca/nl-status02

Added by Wojciech Kapcia TigaseTeam over 5 years ago

So, as per asterisk configuration:

serverhost=asterisk.mydomain.tld
pubsub_node=pubsub.asterisk.mydomain.tld

you should use configuration that matches your VHost:

serverhost=networklab.ca
pubsub_node=pubsub.networklab.ca

This confirms my suspicious about S2S attempt explained before.

Added by Slava Bendersky over 5 years ago

Hello Wojciech,

Thank you for you time, I made changes per you suggestion. Here some issue with pub sub table in DB. Is this something possible to fix ?

2013-12-14 00:24:01.507 [in_6-message-router]  MessageRouter.getLocalComponent()  FINEST: Still no comp name matches: pubsub.networklab.ca, for map: {cl-comp=tigase.cluster.ClusterConnectionManager@6dffcd26, c2s=tigase.cluster.ClientConnectionClustered@7291ca34, basic-conf=tigase.conf.Configurator@ded0b93, s2s=tigase.cluster.S2SConnectionClustered@e57bd52, cluster-contr=tigase.cluster.ClusterController@7ad66ecc, bosh=tigase.cluster.BoshConnectionClustered@47d052c3, vhost-man=tigase.vhosts.VHostManager@4592e709, sess-man=tigase.cluster.SessionManagerClustered@7d9d1044, ws2s=tigase.cluster.WebSocketClientConnectionClustered@4cbd23c8, message-router=tigase.server.MessageRouter@2f7e238e, stats=tigase.stats.StatisticsCollector@552ee43b, pubsub=tigase.pubsub.PubSubComponent@7c5b6f4a, amp=tigase.server.amp.AmpComponent@2ae1ef17, monitor=tigase.cluster.MonitorClustered@a678505, muc=tigase.muc.MUCComponent@3b897b54}, for all VHosts: {3}
2013-12-14 00:24:01.507 [in_6-message-router]  MessageRouter.processPacket()  FINEST:   1. Packet will be processed by: pubsub@xmpp01.networklab.ca, from=sess-man@xmpp01.networklab.ca, to=null, DATA=<iq xmlns="jabber:client" type="set" to="pubsub.networklab.ca" from="delta@networklab.ca/nl-status01" id="aaabe"><pubsub xmlns="http://jabber.org/protocol/pubsub"><publish node="device_state"><item id="SIP/110"><state cachable="1" xmlns="http://asterisk.org" eid="00:0c:29:86:5b:25">NOT_INUSE</state></item></publish></pubsub></iq>, SIZE=331, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=set
2013-12-14 00:24:01.511 [in_0-pubsub]      AbstractMessageReceiver$QueueListener.run()  SEVERE: [in_0-pubsub] Exception during packet processing: from=sess-man@xmpp01.networklab.ca, to=null, DATA=<iq xmlns="jabber:client" type="set" to="pubsub.networklab.ca" from="delta@networklab.ca/nl-status01" id="aaabe"><pubsub xmlns="http://jabber.org/protocol/pubsub"><publish node="device_state"><item id="SIP/110"><state cachable="1" xmlns="http://asterisk.org" eid="00:0c:29:86:5b:25">NOT_INUSE</state></item></publish></pubsub></iq>, SIZE=331, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=set
java.lang.RuntimeException: tigase.pubsub.repository.RepositoryException: Item writing error
    at tigase.pubsub.modules.PublishItemModule.process(PublishItemModule.java:511)
    at tigase.component2.modules.ModulesManager.process(ModulesManager.java:87)
    at tigase.component2.AbstractComponent.processStanzaPacket(AbstractComponent.java:200)
    at tigase.component2.AbstractComponent.processPacket(AbstractComponent.java:188)
    at tigase.server.AbstractMessageReceiver$QueueListener.run(AbstractMessageReceiver.java:1475)
Caused by: tigase.pubsub.repository.RepositoryException: Item writing error
    at tigase.pubsub.repository.PubSubDAOJDBC.writeItem(PubSubDAOJDBC.java:627)
    at tigase.pubsub.repository.cached.Items.writeItem(Items.java:52)
    at tigase.pubsub.modules.PublishItemModule.process(PublishItemModule.java:498)
    at tigase.component2.modules.ModulesManager.process(ModulesManager.java:87)
    at tigase.component2.AbstractComponent.processStanzaPacket(AbstractComponent.java:200)
    at tigase.component2.AbstractComponent.processPacket(AbstractComponent.java:188)
    at tigase.server.AbstractMessageReceiver$QueueListener.run(AbstractMessageReceiver.java:1475)
Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLSyntaxErrorException: Incorrect number of arguments for PROCEDURE tigasedb.TigPubSubWriteItem; expected 6, got 5
    at sun.reflect.GeneratedConstructorAccessor28.newInstance(Unknown Source)
    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:411)
    at com.mysql.jdbc.Util.getInstance(Util.java:386)
    at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1052)
    at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3597)
    at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3529)
    at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1990)
    at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2151)
    at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2625)
    at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2119)
    at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:2283)
    at com.mysql.jdbc.CallableStatement.executeQuery(CallableStatement.java:943)
    at tigase.pubsub.repository.PubSubDAOJDBC.writeItem(PubSubDAOJDBC.java:619)
    at tigase.pubsub.repository.cached.Items.writeItem(Items.java:52)
    at tigase.pubsub.modules.PublishItemModule.process(PublishItemModule.java:498)
    at tigase.component2.modules.ModulesManager.process(ModulesManager.java:87)
    at tigase.component2.AbstractComponent.processStanzaPacket(AbstractComponent.java:200)
    at tigase.component2.AbstractComponent.processPacket(AbstractComponent.java:188)
    at tigase.server.AbstractMessageReceiver$QueueListener.run(AbstractMessageReceiver.java:1475)

Added by Wojciech Kapcia TigaseTeam over 5 years ago

There was a bug in the schema. Running following query should fix the problem:

drop procedure if exists TigPubSubWriteItem //
create procedure TigPubSubWriteItem(_service_jid varchar(2049), _node_name text, _item_id text, _publisher varchar(2047), _item_data mediumtext)
begin
  insert into tig_pubsub_items (service_jid_sha1, node_name_sha1, id, creation_date, update_date, publisher, data)
    values (SHA1(_service_jid), SHA1(_node_name), _item_id, now(), now(), _publisher, _item_data)
    on duplicate key update publisher = _publisher, data = _item_data, update_date = now();
end //

Added by Slava Bendersky over 5 years ago

Hello Wojciech,

I updated procedure in DB and getting this message.

2013-12-16 21:28:35.229 [in_0-pubsub]      AbstractMessageReceiver$QueueListener.run()  SEVERE: [in_0-pubsub] Exception during packet processing: from=sess-man@xmpp01.networklab.ca, to=null, DATA=<iq to="pubsub.networklab.ca" id="aazxx" xmlns="jabber:client" type="set" from="delta@networklab.ca/nl-status01"><pubsub xmlns="http://jabber.org/protocol/pubsub"><publish node="device_state"><item id="SIP/110"><state xmlns="http://asterisk.org" eid="00:0c:29:86:5b:25" cachable="1">NOT_INUSE</state></item></publish></pubsub></iq>, SIZE=331, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=set
java.lang.RuntimeException: tigase.pubsub.repository.RepositoryException: Item field 4 parsing error
    at tigase.pubsub.modules.PublishItemModule.process(PublishItemModule.java:511)
    at tigase.component2.modules.ModulesManager.process(ModulesManager.java:87)
    at tigase.component2.AbstractComponent.processStanzaPacket(AbstractComponent.java:200)
    at tigase.component2.AbstractComponent.processPacket(AbstractComponent.java:188)
    at tigase.server.AbstractMessageReceiver$QueueListener.run(AbstractMessageReceiver.java:1475)
Caused by: tigase.pubsub.repository.RepositoryException: Item field 4 parsing error
    at tigase.pubsub.repository.PubSubDAOJDBC.getDateFromItem(PubSubDAOJDBC.java:231)
    at tigase.pubsub.repository.PubSubDAOJDBC.getItemUpdateDate(PubSubDAOJDBC.java:277)
    at tigase.pubsub.repository.cached.Items.getItemUpdateDate(Items.java:47)
    at tigase.pubsub.modules.PublishItemModule.trimItems(PublishItemModule.java:557)
    at tigase.pubsub.modules.PublishItemModule.process(PublishItemModule.java:501)
    at tigase.component2.modules.ModulesManager.process(ModulesManager.java:87)
    at tigase.component2.AbstractComponent.processStanzaPacket(AbstractComponent.java:200)
    at tigase.component2.AbstractComponent.processPacket(AbstractComponent.java:188)
    at tigase.server.AbstractMessageReceiver$QueueListener.run(AbstractMessageReceiver.java:1475)
Caused by: java.text.ParseException: Unparseable date: "2013-12-16 21:28:35.0"
    at java.text.DateFormat.parse(DateFormat.java:357)
    at tigase.pubsub.repository.PubSubDAOJDBC.getDateFromItem(PubSubDAOJDBC.java:224)
    at tigase.pubsub.repository.PubSubDAOJDBC.getItemUpdateDate(PubSubDAOJDBC.java:277)
    at tigase.pubsub.repository.cached.Items.getItemUpdateDate(Items.java:47)
    at tigase.pubsub.modules.PublishItemModule.trimItems(PublishItemModule.java:557)
    at tigase.pubsub.modules.PublishItemModule.process(PublishItemModule.java:501)
    at tigase.component2.modules.ModulesManager.process(ModulesManager.java:87)
    at tigase.component2.AbstractComponent.processStanzaPacket(AbstractComponent.java:200)
    at tigase.component2.AbstractComponent.processPacket(AbstractComponent.java:188)
    at tigase.server.AbstractMessageReceiver$QueueListener.run(AbstractMessageReceiver.java:1475)

Added by Wojciech Kapcia TigaseTeam over 5 years ago

Have you changed locale or migrated from the OS that has different locale setting than the one you are currently using?

Added by Slava Bendersky over 5 years ago

No, it all the time running on rhel.

Added by Wojciech Kapcia TigaseTeam over 5 years ago

OK, but on the exact same machine & same installation? Basically above exception most likely stems from the change in locale - date was stored with one and then locale changes and the Java parser tries to use the default one for the system locale and it fails.

Added by Slava Bendersky over 5 years ago

Yes, this machine online about year in half online and I didn't do it recently any changes.

Added by Wojciech Kapcia TigaseTeam over 5 years ago

And the mysql is on the same machine? What are the locales there?

Added by Slava Bendersky over 5 years ago

Mysql is not on same machine. It separate cluster.

Added by Wojciech Kapcia TigaseTeam over 5 years ago

Could you confirm, that both machines have seme locale set?

Added by Slava Bendersky over 5 years ago

Hello Wojciech,

Yes, I double check both machines setting and they are the same.

Added by Wojciech Kapcia TigaseTeam over 5 years ago

OK, given all the information you provided I couldn't replicate the issue nor see anything wrong except for the mismatch of locales but that should be ruled out according to you.

Side question - does the issue persist on a freshly created PubSub Schema?

While on the topic I can say that the PubSub schema will be undergo a rework in future though.

Added by Slava Bendersky over 5 years ago

Hello Wojciech,

Yes, I stopped server, removed pubsub tables from DB and created again with this schema.

But message still persist time to time. I see this

Caused by: java.text.ParseException: Unparseable date: "2013-12-19 15:36:53.0"
    at java.text.DateFormat.parse(DateFormat.java:357)

CREATE  TABLE IF NOT EXISTS tig_pubsub_nodes (
 `service_jid` VARCHAR(2049) NOT NULL  /* Service JID */,
 `service_jid_sha1` CHAR(40) NOT NULL  /* SHA1 hash of service_jid_sha1 */,
 `name` TEXT NOT NULL  /* Node name (unique with service_jid). */ ,
 `name_sha1` CHAR(40) NOT NULL  /* SHA1 hash of node_name used for uniqueness */,
 `type` INT(1) NOT NULL  /* Node type (0:collection, 1:leaf). */ ,
 `title` VARCHAR(1000) NULL  /* A friendly name for the node. */ ,
 `description` TEXT  /* A description of the node. */ ,
 `creator` VARCHAR(2047) NULL  /* The JID of the node creator. */ ,
 `creation_date` DATETIME NULL  /* The datetime when the node was created. */ ,
 `configuration` MEDIUMTEXT NULL ,
 `affiliations` MEDIUMTEXT NULL ,
 PRIMARY KEY (`service_jid_sha1`(40), `name_sha1`(40)),
 INDEX USING HASH (`service_jid`(255)),
 INDEX USING HASH (`name`(255))
)
ENGINE=InnoDB default character set utf8 ROW_FORMAT=DYNAMIC;
/* This node table contains attributes which are common to both node types. */

CREATE  TABLE IF NOT EXISTS tig_pubsub_items (
 `service_jid_sha1` CHAR(40) NOT NULL,
 `node_name_sha1` CHAR(40) NOT NULL,
 `id` TEXT NOT NULL,
 `creation_date` DATETIME NULL,
 `publisher` VARCHAR(2047) NULL,
 `update_date` DATETIME NULL,
 `data` MEDIUMTEXT NULL,
 PRIMARY KEY USING HASH (`service_jid_sha1`(40),`node_name_sha1`(40), `id`(255)),
 INDEX (`id`(255)),
 CONSTRAINT
  FOREIGN KEY (`service_jid_sha1`, `node_name_sha1`)
  REFERENCES `tig_pubsub_nodes`(`service_jid_sha1`, `name_sha1`)
  MATCH FULL
  ON DELETE CASCADE
)
ENGINE=InnoDB default character set utf8 ROW_FORMAT=DYNAMIC;
/* Items stored by persistent nodes. */

CREATE  TABLE IF NOT EXISTS tig_pubsub_subscriptions (
 `service_jid_sha1` CHAR(40) NOT NULL,
 `node_name_sha1` CHAR(40) NOT NULL,
 `index` BIGINT NOT NULL,
 `data` MEDIUMTEXT NULL,
 PRIMARY KEY (`service_jid_sha1`(40),`node_name_sha1`(40),`index`),
 CONSTRAINT
  FOREIGN KEY (`service_jid_sha1`,`node_name_sha1`)
  REFERENCES `tig_pubsub_nodes`(`service_jid_sha1`,`name_sha1`)
  MATCH FULL
  ON DELETE CASCADE
)
ENGINE=InnoDB default character set utf8 ROW_FORMAT=DYNAMIC;
/* Node subscriptions. */


delimiter //

-- Create node
drop procedure if exists TigPubSubCreateNode //
create procedure TigPubSubCreateNode(_service_jid varchar(2049), _node_name text, _node_type int(1), _node_creator varchar(2047), _node_conf mediumtext)
begin
  insert into tig_pubsub_nodes (service_jid, service_jid_sha1, name, name_sha1, type, creator, creation_date, configuration)
    values (_service_jid, SHA1(_service_jid), _node_name, SHA1(_node_name), _node_type, _node_creator, now(), _node_conf);
end //

-- Remove node
drop procedure if exists TigPubSubRemoveNode //
create procedure TigPubSubRemoveNode(_service_jid varchar(2049), _node_name text)
begin
  delete from tig_pubsub_items where service_jid_sha1 = SHA1(_service_jid) and node_name_sha1 = SHA1(_node_name);
  delete from tig_pubsub_subscriptions where service_jid_sha1 = SHA1(_service_jid) and node_name_sha1 = SHA1(_node_name);
  delete from tig_pubsub_nodes where service_jid_sha1 = SHA1(_service_jid) and name_sha1 = SHA1(_node_name);
end //

-- Get item of the node
drop procedure if exists TigPubSubGetItem //
create procedure TigPubSubGetItem(_service_jid varchar(2049), _node_name text, _item_id text)
begin
  select data, publisher, creation_date, update_date
    from tig_pubsub_items where service_jid_sha1 = SHA1(_service_jid) AND node_name_sha1 = SHA1(_node_name) AND id = _item_id;
end //

-- Write item of the node
drop procedure if exists TigPubSubWriteItem //
create procedure TigPubSubWriteItem(_service_jid varchar(2049), _node_name text, _item_id text, _publisher varchar(2047), _item_data mediumtext)
begin
  insert into tig_pubsub_items (service_jid_sha1, node_name_sha1, id, creation_date, update_date, publisher, data)
    values (SHA1(_service_jid), SHA1(_node_name), _item_id, now(), now(), _publisher, _item_data)
    on duplicate key update publisher = _publisher, data = _item_data, update_date = now();
end //

-- Delete item
drop procedure if exists TigPubSubDeleteItem //
create procedure TigPubSubDeleteItem(_service_jid varchar(2049), _node_name text, _item_id text)
begin
  delete from tig_pubsub_items where service_jid_sha1 = SHA1(_service_jid) AND node_name_sha1 = SHA1(_node_name) AND id = _item_id ;
end //

-- Get node's item IDs
drop procedure if exists TigPubSubGetNodeItemsIds //
create procedure TigPubSubGetNodeItemsIds(_service_jid varchar(2049), _node_name text)
begin
  select id from tig_pubsub_items where service_jid_sha1 = SHA1(_service_jid) AND node_name_sha1 = SHA1(_node_name) order by creation_date;
end //

-- Get all nodes names
drop procedure if exists TigPubSubGetAllNodes //
create procedure TigPubSubGetAllNodes(_service_jid varchar(2049))
begin
  select name from tig_pubsub_nodes where  service_jid_sha1 = SHA1(_service_jid);
end //

-- Delete all nodes
drop procedure if exists TigPubSubDeleteAllNodes //
create procedure TigPubSubDeleteAllNodes(_service_jid varchar(2049))
begin
  delete from tig_pubsub_items where service_jid_sha1 = SHA1(_service_jid);
  delete from tig_pubsub_subscriptions where service_jid_sha1 = SHA1(_service_jid);
  delete from tig_pubsub_nodes where service_jid_sha1 = SHA1(_service_jid);
end //

-- Set node configuration
drop procedure if exists TigPubSubSetNodeConfiguration //
create procedure TigPubSubSetNodeConfiguration(_service_jid varchar(2049), _node_name text, _node_conf mediumtext)
begin
  update tig_pubsub_nodes set configuration = _node_conf where service_jid_sha1 = SHA1(_service_jid) AND name_sha1 = SHA1(_node_name);
end //

-- Set node affiliations
drop procedure if exists TigPubSubSetNodeAffiliations //
create procedure TigPubSubSetNodeAffiliations(_service_jid varchar(2049), _node_name text, _node_aff mediumtext)
begin
  update tig_pubsub_nodes set affiliations = _node_aff where service_jid_sha1 = SHA1(_service_jid) AND name_sha1 = SHA1(_node_name);
end //

-- Get node configuration
drop procedure if exists TigPubSubGetNodeConfiguration //
create procedure TigPubSubGetNodeConfiguration(_service_jid varchar(2049), _node_name text)
begin
  select configuration from tig_pubsub_nodes where service_jid_sha1 = SHA1(_service_jid) AND name_sha1 = SHA1(_node_name);
end //

-- Get node affiliations
drop procedure if exists TigPubSubGetNodeAffiliations //
create procedure TigPubSubGetNodeAffiliations(_service_jid varchar(2049), _node_name text)
begin
  select affiliations from tig_pubsub_nodes where service_jid_sha1 = SHA1(_service_jid) AND name_sha1 = SHA1(_node_name);
end //

-- Get node subscriptions
drop procedure if exists TigPubSubGetNodeSubscriptions //
create procedure TigPubSubGetNodeSubscriptions(_service_jid varchar(2049), _node_name text)
begin
  select data from tig_pubsub_subscriptions where service_jid_sha1 = SHA1(_service_jid) AND node_name_sha1 = SHA1(_node_name) order by `index` ;
end //

-- Set node subscription
drop procedure if exists TigPubSubSetNodeSubscriptions //
create procedure TigPubSubSetNodeSubscriptions(_service_jid varchar(2049), _node_name text, _node_index bigint, _node_data mediumtext)
begin
  insert into tig_pubsub_subscriptions (service_jid_sha1, node_name_sha1, `index`, data)
    values (SHA1(_service_jid), SHA1(_node_name), _node_index, _node_data)
    on duplicate key update data = _node_data;
end //

-- Delete node subscription
drop procedure if exists TigPubSubDeleteNodeSubscriptions //
create procedure TigPubSubDeleteNodeSubscriptions(_service_jid varchar(2049), _node_name text, _node_index bigint)
begin
  delete from tig_pubsub_subscriptions where service_jid_sha1 = SHA1(_service_jid) AND node_name_sha1 = SHA1(_node_name) AND `index` = _node_index ;
end //


delimiter ;

-- Helper function for calculating number of subscriptions in database
drop function if exists substrCount;
CREATE FUNCTION substrCount(x mediumtext, delim varchar(12)) returns int return (length(x)-length(REPLACE(x, delim, '')))/length(delim);

(1-25/29)