Clustering strategy sends the packet twice (#1061)

Activities

Wojciech Kapcia (Tigase) opened 6 years ago

2019-08-12 17:37:40.438 [pool-36-thread-2]  S2SConnectionManager.processSocketData()  FINEST: Processing socket data: from=null, to=null, DATA=<message type="chat" from="wojtek@jabster.pl/Psi+" xml:lang="en" to="wojtek@tigase.im/firefly/psi+/green" id="wojtekDuplicateMessageTest4343"><body>CData size: 30</body></message>, SIZE=195, XMLNS=null, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=chat
2019-08-12 17:37:40.438 [pool-36-thread-2]  S2SConnectionManager.processSocketData()  FINEST: CID: tigase.im@jabster.pl, null, type: accept, Socket: TLS: nullSocket[addr=/95.168.217.72,port=40334,localport=5269], jid: null, Adding packet out: from=null, to=null, DATA=<message type="chat" from="wojtek@jabster.pl/Psi+" xml:lang="en" to="wojtek@tigase.im/firefly/psi+/green" id="wojtekDuplicateMessageTest4343" xmlns="jabber:client"><body>CData size: 30</body></message>, SIZE=217, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=chat
2019-08-12 17:37:40.439 [in_5-message-router]  MessageRouter.processPacket()       FINEST:   Processing packet: from=s2s@ip-10-0-12-136.us-west-2.compute.internal, to=null, DATA=<message type="chat" from="wojtek@jabster.pl/Psi+" xml:lang="en" to="wojtek@tigase.im/firefly/psi+/green" id="wojtekDuplicateMessageTest4343" xmlns="jabber:client"><body>CData size: 30</body></message>, SIZE=217, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=REMOTE, TYPE=chat
2019-08-12 17:37:40.439 [in_5-message-router]  MessageRouter.getLocalComponent()   FINEST:   Component match failed: wojtek@tigase.im/firefly/psi+/green, for comp: [ext, vhost-man, upload, c2s, amp, ws2s, monitor, bosh, push, cl-comp, proxy, s2s, stats, eventbus, http, muc, message-archive, sess-man, cluster-contr, message-router, pubsub], basename: im
2019-08-12 17:37:40.439 [in_5-message-router]  MessageRouter.processPacket()       FINEST:   2. Packet will be processed by: sess-man@ip-10-0-12-136.us-west-2.compute.internal, from=s2s@ip-10-0-12-136.us-west-2.compute.internal, to=null, DATA=<message type="chat" from="wojtek@jabster.pl/Psi+" xml:lang="en" to="wojtek@tigase.im/firefly/psi+/green" id="wojtekDuplicateMessageTest4343" xmlns="jabber:client"><body>CData size: 30</body></message>, SIZE=217, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=REMOTE, TYPE=chat
2019-08-12 17:37:40.439 [in_13-sess-man]   SessionManagerClustered.processPacket()  FINEST:  Received packet: from=s2s@ip-10-0-12-136.us-west-2.compute.internal, to=null, DATA=<message type="chat" from="wojtek@jabster.pl/Psi+" xml:lang="en" to="wojtek@tigase.im/firefly/psi+/green" id="wojtekDuplicateMessageTest4343" xmlns="jabber:client"><body>CData size: 30</body></message>, SIZE=217, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=REMOTE, TYPE=chat
2019-08-12 17:37:40.439 [in_13-sess-man]   SessionManager.getXMPPResourceConnection()  FINEST: Searching for resource connection for: wojtek@tigase.im/firefly/psi+/green
2019-08-12 17:37:40.439 [in_13-sess-man]   SessionManagerClustered.processPacket()  FINEST:  Ressource connection found: null
2019-08-12 17:37:40.439 [in_13-sess-man]   OnlineUsersCachingStrategy.getNodesForPacketForward()  FINEST: Selected nodes: [sess-man@ip-10-0-28-108.us-west-2.compute.internal], for packet: from=s2s@ip-10-0-12-136.us-west-2.compute.internal, to=null, DATA=<message type="chat" from="wojtek@jabster.pl/Psi+" xml:lang="en" to="wojtek@tigase.im/firefly/psi+/green" id="wojtekDuplicateMessageTest4343" xmlns="jabber:client"><body>CData size: 30</body></message>, SIZE=217, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=REMOTE, TYPE=chat
2019-08-12 17:37:40.439 [in_13-sess-man]   DefaultClusteringStrategyAbstract.processPacket()  FINEST: Forwarding packet from=s2s@ip-10-0-12-136.us-west-2.compute.internal, to=null, DATA=<message type="chat" from="wojtek@jabster.pl/Psi+" xml:lang="en" to="wojtek@tigase.im/firefly/psi+/green" id="wojtekDuplicateMessageTest4343" xmlns="jabber:client"><body>CData size: 30</body></message>, SIZE=217, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=REMOTE, TYPE=chat to nodes: [sess-man@ip-10-0-28-108.us-west-2.compute.internal]
2019-08-12 17:37:40.439 [in_13-sess-man]   ClusterElement.<init>()                 FINEST:   Parsing cluster element: <cluster to="sess-man@ip-10-0-28-108.us-west-2.compute.internal" type="set" from="sess-man@ip-10-0-12-136.us-west-2.compute.internal" xmlns="tigase:cluster"><control><visited-nodes/><method-call name="sess-man-packet-forward-sm-cmd"><par name="packet-from">s2s@ip-10-0-12-136.us-west-2.compute.internal</par></method-call></control></cluster>
2019-08-12 17:37:40.439 [in_13-sess-man]   ClusterElement.<init>()                 FINEST:   First node found: null
2019-08-12 17:37:40.439 [in_13-sess-man]   ClusterElement.<init>()                 FINEST:   No visited nodes found
2019-08-12 17:37:40.439 [in_13-sess-man]   ClusterConnectionManager$SendPacket.executeCommand()  FINEST: Called fromNode: null, visitedNodes: null, data: null, packets: [<cluster type="set" from="sess-man@ip-10-0-12-136.us-west-2.compute.internal" to="sess-man@ip-10-0-28-108.us-west-2.compute.internal" pr="HIGH" xmlns="tigase:cluster" id="cl-3019818"><control><visited-nodes><node-id>sess-man@ip-10-0-12-136.us-west-2.compute.internal</node-id></visited-nodes><method-call name="sess-man-packet-forward-sm-cmd"><par name="packet-from">s2s@ip-10-0-12-136.us-west-2.compute.internal</par></method-call><first-node>sess-man@ip-10-0-12-136.us-west-2.compute.internal</first-node></control><data><message type="chat" from="wojtek@jabster.pl/Psi+" xml:lang="en" to="wojtek@tigase.im/firefly/psi+/green" id="wojtekDuplicateMessageTest4343" xmlns="jabber:client"><body>wojtekDuplicateMessageTest4343</body></message></data></cluster>]
2019-08-12 17:37:40.439 [in_13-sess-man]   ClusterElement.<init>()                 FINEST:   Parsing cluster element: <cluster type="set" from="sess-man@ip-10-0-12-136.us-west-2.compute.internal" to="sess-man@ip-10-0-28-108.us-west-2.compute.internal" pr="HIGH" xmlns="tigase:cluster" id="cl-3019818"><control><visited-nodes><node-id>sess-man@ip-10-0-12-136.us-west-2.compute.internal</node-id></visited-nodes><method-call name="sess-man-packet-forward-sm-cmd"><par name="packet-from">s2s@ip-10-0-12-136.us-west-2.compute.internal</par></method-call><first-node>sess-man@ip-10-0-12-136.us-west-2.compute.internal</first-node></control><data><message type="chat" from="wojtek@jabster.pl/Psi+" xml:lang="en" to="wojtek@tigase.im/firefly/psi+/green" id="wojtekDuplicateMessageTest4343" xmlns="jabber:client"><body>wojtekDuplicateMessageTest4343</body></message></data></cluster>
2019-08-12 17:37:40.439 [in_13-sess-man]   ClusterElement.<init>()                 FINEST:   First node found: sess-man@ip-10-0-12-136.us-west-2.compute.internal
2019-08-12 17:37:40.439 [in_13-sess-man]   ClusterElement.<init>()                 FINEST:   Found and added visited nodes: 1
2019-08-12 17:37:40.439 [in_13-sess-man]   SessionManagerClustered.processPacket()  FINEST:  Ignoring/dropping packet: from=sess-man@ip-10-0-12-136.us-west-2.compute.internal, to=null, DATA=<message type="chat" from="wojtek@jabster.pl/Psi+" xml:lang="en" to="wojtek@tigase.im/firefly/psi+/green" id="wojtekDuplicateMessageTest4343" xmlns="jabber:client"><body>CData size: 30</body></message>, SIZE=217, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=REMOTE, TYPE=chat
2019-08-12 17:37:40.439 [in_15-cl-comp]    ClusterConnectionManager.processPacket()  FINEST: Processing packet: from=null, to=null, DATA=<cluster type="set" from="sess-man@ip-10-0-12-136.us-west-2.compute.internal" to="sess-man@ip-10-0-28-108.us-west-2.compute.internal" pr="HIGH" xmlns="tigase:cluster" id="cl-3019818"><control><visited-nodes><node-id>CData size: 50</node-id></visited-nodes><method-call name="sess-man-packet-forward-sm-cmd"><par name="packet-from">CData size: 45</par></method-call><first-node>CData size: 50</first-node></control><data><message type="chat" from="wojtek@jabster.pl/Psi+" xml:lang="en" to="wojtek@tigase.im/firefly/psi+/green" id="wojtekDuplicateMessageTest4343" xmlns="jabber:client"><body>CData size: 30</body></message></data></cluster>, SIZE=757, XMLNS=tigase:cluster, PRIORITY=HIGH, PERMISSION=NONE, TYPE=set
2019-08-12 17:37:40.439 [in_7-message-router]  MessageRouter.processPacket()       FINEST:   Processing packet: from=sess-man@ip-10-0-12-136.us-west-2.compute.internal, to=null, DATA=<message type="chat" from="wojtek@jabster.pl/Psi+" xml:lang="en" to="wojtek@tigase.im/firefly/psi+/green" id="wojtekDuplicateMessageTest4343" xmlns="jabber:client"><body>CData size: 30</body></message>, SIZE=217, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=REMOTE, TYPE=chat
2019-08-12 17:37:40.439 [in_7-message-router]  MessageRouter.getLocalComponent()   FINEST:   Called for : wojtek@tigase.im/firefly/psi+/green
…
2019-08-12 17:37:40.440 [in_7-message-router]  MessageRouter.getLocalComponent()   FINEST:   Component match failed: wojtek@tigase.im/firefly/psi+/green, for comp: [ext, vhost-man, upload, c2s, amp, ws2s, monitor, bosh, push, cl-comp, proxy, s2s, stats, eventbus, http, muc, message-archive, sess-man, cluster-contr, message-router, pubsub], basename: im
2019-08-12 17:37:40.440 [in_7-message-router]  MessageRouter.processPacket()       FINEST:   2. Packet will be processed by: sess-man@ip-10-0-12-136.us-west-2.compute.internal, from=sess-man@ip-10-0-12-136.us-west-2.compute.internal, to=null, DATA=<message type="chat" from="wojtek@jabster.pl/Psi+" xml:lang="en" to="wojtek@tigase.im/firefly/psi+/green" id="wojtekDuplicateMessageTest4343" xmlns="jabber:client"><body>CData size: 30</body></message>, SIZE=217, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=REMOTE, TYPE=chat
2019-08-12 17:37:40.439 [in_15-cl-comp]    ClusterElement.<init>()                 FINEST:   Parsing cluster element: <cluster type="set" from="sess-man@ip-10-0-12-136.us-west-2.compute.internal" to="sess-man@ip-10-0-28-108.us-west-2.compute.internal" pr="HIGH" xmlns="tigase:cluster" id="cl-3019818"><control><visited-nodes><node-id>sess-man@ip-10-0-12-136.us-west-2.compute.internal</node-id></visited-nodes><method-call name="sess-man-packet-forward-sm-cmd"><par name="packet-from">s2s@ip-10-0-12-136.us-west-2.compute.internal</par></method-call><first-node>sess-man@ip-10-0-12-136.us-west-2.compute.internal</first-node></control><data><message type="chat" from="wojtek@jabster.pl/Psi+" xml:lang="en" to="wojtek@tigase.im/firefly/psi+/green" id="wojtekDuplicateMessageTest4343" xmlns="jabber:client"><body>wojtekDuplicateMessageTest4343</body></message></data></cluster>
2019-08-12 17:37:40.440 [in_7-sess-man]    SessionManagerClustered.processPacket()  FINEST:  Received packet: from=sess-man@ip-10-0-12-136.us-west-2.compute.internal, to=null, DATA=<message type="chat" from="wojtek@jabster.pl/Psi+" xml:lang="en" to="wojtek@tigase.im/firefly/psi+/green" id="wojtekDuplicateMessageTest4343" xmlns="jabber:client"><body>CData size: 30</body></message>, SIZE=217, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=REMOTE, TYPE=chat
2019-08-12 17:37:40.440 [in_7-sess-man]    SessionManager.getXMPPResourceConnection()  FINEST: Searching for resource connection for: wojtek@tigase.im/firefly/psi+/green
2019-08-12 17:37:40.440 [in_7-sess-man]    SessionManagerClustered.processPacket()  FINEST:  Ressource connection found: null
2019-08-12 17:37:40.440 [in_7-sess-man]    OnlineUsersCachingStrategy.getNodesForPacketForward()  FINEST: Selected nodes: [sess-man@ip-10-0-28-108.us-west-2.compute.internal], for packet: from=sess-man@ip-10-0-12-136.us-west-2.compute.internal, to=null, DATA=<message type="chat" from="wojtek@jabster.pl/Psi+" xml:lang="en" to="wojtek@tigase.im/firefly/psi+/green" id="wojtekDuplicateMessageTest4343" xmlns="jabber:client"><body>CData size: 30</body></message>, SIZE=217, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=REMOTE, TYPE=chat
2019-08-12 17:37:40.440 [in_7-sess-man]    DefaultClusteringStrategyAbstract.processPacket()  FINEST: Forwarding packet from=sess-man@ip-10-0-12-136.us-west-2.compute.internal, to=null, DATA=<message type="chat" from="wojtek@jabster.pl/Psi+" xml:lang="en" to="wojtek@tigase.im/firefly/psi+/green" id="wojtekDuplicateMessageTest4343" xmlns="jabber:client"><body>CData size: 30</body></message>, SIZE=217, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=REMOTE, TYPE=chat to nodes: [sess-man@ip-10-0-28-108.us-west-2.compute.internal]
2019-08-12 17:37:40.440 [in_15-cl-comp]    ClusterElement.<init>()                 FINEST:   First node found: sess-man@ip-10-0-12-136.us-west-2.compute.internal
2019-08-12 17:37:40.440 [in_7-sess-man]    ClusterElement.<init>()                 FINEST:   Parsing cluster element: <cluster to="sess-man@ip-10-0-28-108.us-west-2.compute.internal" type="set" from="sess-man@ip-10-0-12-136.us-west-2.compute.internal" xmlns="tigase:cluster"><control><visited-nodes/><method-call name="sess-man-packet-forward-sm-cmd"><par name="packet-from">sess-man@ip-10-0-12-136.us-west-2.compute.internal</par></method-call></control></cluster>
2019-08-12 17:37:40.440 [in_7-sess-man]    ClusterElement.<init>()                 FINEST:   First node found: null
2019-08-12 17:37:40.440 [in_7-sess-man]    ClusterElement.<init>()                 FINEST:   No visited nodes found
2019-08-12 17:37:40.440 [in_15-cl-comp]    ClusterElement.<init>()                 FINEST:   Found and added visited nodes: 1
2019-08-12 17:37:40.440 [in_7-sess-man]    ClusterConnectionManager$SendPacket.executeCommand()  FINEST: Called fromNode: null, visitedNodes: null, data: null, packets: [<cluster type="set" from="sess-man@ip-10-0-12-136.us-west-2.compute.internal" to="sess-man@ip-10-0-28-108.us-west-2.compute.internal" pr="HIGH" xmlns="tigase:cluster" id="cl-3019819"><control><visited-nodes><node-id>sess-man@ip-10-0-12-136.us-west-2.compute.internal</node-id></visited-nodes><method-call name="sess-man-packet-forward-sm-cmd"><par name="packet-from">sess-man@ip-10-0-12-136.us-west-2.compute.internal</par></method-call><first-node>sess-man@ip-10-0-12-136.us-west-2.compute.internal</first-node></control><data><message type="chat" from="wojtek@jabster.pl/Psi+" xml:lang="en" to="wojtek@tigase.im/firefly/psi+/green" id="wojtekDuplicateMessageTest4343" xmlns="jabber:client"><body>wojtekDuplicateMessageTest4343</body></message></data></cluster>]
2019-08-12 17:37:40.440 [in_15-cl-comp]    ConnectionManager.writePacketToSocket()  FINEST:  null, type: accept, Socket: nullSocket[addr=/10.0.28.108,port=57005,localport=5277], jid: ip-10-0-28-108.us-west-2.compute.internal, Writing packet: from=null, to=null, DATA=<cluster type="set" from="sess-man@ip-10-0-12-136.us-west-2.compute.internal" to="sess-man@ip-10-0-28-108.us-west-2.compute.internal" pr="HIGH" xmlns="tigase:cluster" id="cl-3019818"><control><visited-nodes><node-id>CData size: 50</node-id></visited-nodes><method-call name="sess-man-packet-forward-sm-cmd"><par name="packet-from">CData size: 45</par></method-call><first-node>CData size: 50</first-node></control><data><message type="chat" from="wojtek@jabster.pl/Psi+" xml:lang="en" to="wojtek@tigase.im/firefly/psi+/green" id="wojtekDuplicateMessageTest4343" xmlns="jabber:client"><body>CData size: 30</body></message></data></cluster>, SIZE=757, XMLNS=tigase:cluster, PRIORITY=HIGH, PERMISSION=NONE, TYPE=set
2019-08-12 17:37:40.441 [in_7-sess-man]    ClusterElement.<init>()                 FINEST:   Parsing cluster element: <cluster type="set" from="sess-man@ip-10-0-12-136.us-west-2.compute.internal" to="sess-man@ip-10-0-28-108.us-west-2.compute.internal" pr="HIGH" xmlns="tigase:cluster" id="cl-3019819"><control><visited-nodes><node-id>sess-man@ip-10-0-12-136.us-west-2.compute.internal</node-id></visited-nodes><method-call name="sess-man-packet-forward-sm-cmd"><par name="packet-from">sess-man@ip-10-0-12-136.us-west-2.compute.internal</par></method-call><first-node>sess-man@ip-10-0-12-136.us-west-2.compute.internal</first-node></control><data><message type="chat" from="wojtek@jabster.pl/Psi+" xml:lang="en" to="wojtek@tigase.im/firefly/psi+/green" id="wojtekDuplicateMessageTest4343" xmlns="jabber:client"><body>wojtekDuplicateMessageTest4343</body></message></data></cluster>
2019-08-12 17:37:40.441 [in_7-sess-man]    ClusterElement.<init>()                 FINEST:   First node found: sess-man@ip-10-0-12-136.us-west-2.compute.internal
2019-08-12 17:37:40.441 [in_7-sess-man]    ClusterElement.<init>()                 FINEST:   Found and added visited nodes: 1
2019-08-12 17:37:40.441 [in_15-cl-comp]    ClusterConnectionManager.processPacket()  FINEST: Processing packet: from=null, to=null, DATA=<cluster type="set" from="sess-man@ip-10-0-12-136.us-west-2.compute.internal" to="sess-man@ip-10-0-28-108.us-west-2.compute.internal" pr="HIGH" xmlns="tigase:cluster" id="cl-3019819"><control><visited-nodes><node-id>CData size: 50</node-id></visited-nodes><method-call name="sess-man-packet-forward-sm-cmd"><par name="packet-from">CData size: 50</par></method-call><first-node>CData size: 50</first-node></control><data><message type="chat" from="wojtek@jabster.pl/Psi+" xml:lang="en" to="wojtek@tigase.im/firefly/psi+/green" id="wojtekDuplicateMessageTest4343" xmlns="jabber:client"><body>CData size: 30</body></message></data></cluster>, SIZE=762, XMLNS=tigase:cluster, PRIORITY=HIGH, PERMISSION=NONE, TYPE=set
2019-08-12 17:37:40.441 [in_15-cl-comp]    ClusterElement.<init>()                 FINEST:   Parsing cluster element: <cluster type="set" from="sess-man@ip-10-0-12-136.us-west-2.compute.internal" to="sess-man@ip-10-0-28-108.us-west-2.compute.internal" pr="HIGH" xmlns="tigase:cluster" id="cl-3019819"><control><visited-nodes><node-id>sess-man@ip-10-0-12-136.us-west-2.compute.internal</node-id></visited-nodes><method-call name="sess-man-packet-forward-sm-cmd"><par name="packet-from">sess-man@ip-10-0-12-136.us-west-2.compute.internal</par></method-call><first-node>sess-man@ip-10-0-12-136.us-west-2.compute.internal</first-node></control><data><message type="chat" from="wojtek@jabster.pl/Psi+" xml:lang="en" to="wojtek@tigase.im/firefly/psi+/green" id="wojtekDuplicateMessageTest4343" xmlns="jabber:client"><body>wojtekDuplicateMessageTest4343</body></message></data></cluster>
2019-08-12 17:37:40.441 [in_15-cl-comp]    ClusterElement.<init>()                 FINEST:   First node found: sess-man@ip-10-0-12-136.us-west-2.compute.internal
2019-08-12 17:37:40.441 [in_15-cl-comp]    ClusterElement.<init>()                 FINEST:   Found and added visited nodes: 1
2019-08-12 17:37:40.441 [in_15-cl-comp]    ConnectionManager.writePacketToSocket()  FINEST:  null, type: accept, Socket: nullSocket[addr=/10.0.28.108,port=57005,localport=5277], jid: ip-10-0-28-108.us-west-2.compute.internal, Writing packet: from=null, to=null, DATA=<cluster type="set" from="sess-man@ip-10-0-12-136.us-west-2.compute.internal" to="sess-man@ip-10-0-28-108.us-west-2.compute.internal" pr="HIGH" xmlns="tigase:cluster" id="cl-3019819"><control><visited-nodes><node-id>CData size: 50</node-id></visited-nodes><method-call name="sess-man-packet-forward-sm-cmd"><par name="packet-from">CData size: 50</par></method-call><first-node>CData size: 50</first-node></control><data><message type="chat" from="wojtek@jabster.pl/Psi+" xml:lang="en" to="wojtek@tigase.im/firefly/psi+/green" id="wojtekDuplicateMessageTest4343" xmlns="jabber:client"><body>CData size: 30</body></message></data></cluster>, SIZE=762, XMLNS=tigase:cluster, PRIORITY=HIGH, PERMISSION=NONE, TYPE=set

Which results in two packets delivered on subsequent node: 1.

2019-08-12 17:37:40.435 [pool-36-thread-6]  ClusterConnectionManager.processSocketData()  FINEST: Processing socket data: from=null, to=null, DATA=<cluster type="set" xmlns="tigase:cluster" to="sess-man@ip-10-0-28-108.us-west-2.compute.internal" from="sess-man@ip-10-0-12-136.us-west-2.compute.internal" id="cl-3019818" pr="HIGH"><control><visited-nodes><node-id>CData size: 50</node-id></visited-nodes><method-call name="sess-man-packet-forward-sm-cmd"><par name="packet-from">CData size: 45</par></method-call><first-node>CData size: 50</first-node></control><data><message type="chat" xmlns="jabber:client" xml:lang="en" to="wojtek@tigase.im/firefly/psi+/green" from="wojtek@jabster.pl/Psi+" id="wojtekDuplicateMessageTest4343"><body>CData size: 30</body></message></data></cluster>, SIZE=757, XMLNS=tigase:cluster, PRIORITY=HIGH, PERMISSION=NONE, TYPE=set
2019-08-12 17:37:40.435 [pool-36-thread-6]  ClusterElement.<init>()                FINEST:   Parsing cluster element: <cluster type="set" xmlns="tigase:cluster" to="sess-man@ip-10-0-28-108.us-west-2.compute.internal" from="sess-man@ip-10-0-12-136.us-west-2.compute.internal" id="cl-3019818" pr="HIGH"><control><visited-nodes><node-id>sess-man@ip-10-0-12-136.us-west-2.compute.internal</node-id></visited-nodes><method-call name="sess-man-packet-forward-sm-cmd"><par name="packet-from">s2s@ip-10-0-12-136.us-west-2.compute.internal</par></method-call><first-node>sess-man@ip-10-0-12-136.us-west-2.compute.internal</first-node></control><data><message type="chat" xmlns="jabber:client" xml:lang="en" to="wojtek@tigase.im/firefly/psi+/green" from="wojtek@jabster.pl/Psi+" id="wojtekDuplicateMessageTest4343"><body>wojtekDuplicateMessageTest4343</body></message></data></cluster>
2019-08-12 17:37:40.436 [pool-36-thread-6]  ClusterElement.<init>()                FINEST:   First node found: sess-man@ip-10-0-12-136.us-west-2.compute.internal
2019-08-12 17:37:40.436 [pool-36-thread-6]  ClusterElement.<init>()                FINEST:   Found and added visited nodes: 1
2019-08-12 17:37:40.436 [out_15-cl-comp]   ClusterElement.<init>()                 FINEST:   Parsing cluster element: <cluster type="set" xmlns="tigase:cluster" to="sess-man@ip-10-0-28-108.us-west-2.compute.internal" from="sess-man@ip-10-0-12-136.us-west-2.compute.internal" id="cl-3019818" pr="HIGH"><control><visited-nodes><node-id>sess-man@ip-10-0-12-136.us-west-2.compute.internal</node-id></visited-nodes><method-call name="sess-man-packet-forward-sm-cmd"><par name="packet-from">s2s@ip-10-0-12-136.us-west-2.compute.internal</par></method-call><first-node>sess-man@ip-10-0-12-136.us-west-2.compute.internal</first-node></control><data><message type="chat" xmlns="jabber:client" xml:lang="en" to="wojtek@tigase.im/firefly/psi+/green" from="wojtek@jabster.pl/Psi+" id="wojtekDuplicateMessageTest4343"><body>wojtekDuplicateMessageTest4343</body></message></data></cluster>
2019-08-12 17:37:40.436 [out_15-cl-comp]   ClusterElement.<init>()                 FINEST:   First node found: sess-man@ip-10-0-12-136.us-west-2.compute.internal
2019-08-12 17:37:40.436 [out_15-cl-comp]   ClusterElement.<init>()                 FINEST:   Found and added visited nodes: 1
2019-08-12 17:37:40.436 [out_15-cl-comp]   PacketForwardCmd.executeCommand()       FINEST:   Called fromNode: sess-man@ip-10-0-12-136.us-west-2.compute.internal, visitedNodes: [sess-man@ip-10-0-12-136.us-west-2.compute.internal, sess-man@ip-10-0-28-108.us-west-2.compute.internal], data: {packet-from=s2s@ip-10-0-12-136.us-west-2.compute.internal}, packets: [<message type="chat" xmlns="jabber:client" xml:lang="en" to="wojtek@tigase.im/firefly/psi+/green" from="wojtek@jabster.pl/Psi+" id="wojtekDuplicateMessageTest4343"><body>wojtekDuplicateMessageTest4343</body></message>]
2019-08-12 17:37:40.436 [out_15-cl-comp]   SessionManager.getXMPPResourceConnection()  FINEST: Searching for resource connection for: wojtek@tigase.im/firefly/psi+/green
2019-08-12 17:37:40.436 [out_15-cl-comp]   SessionManager.getResourceConnection()  FINEST:   Session not null, searching session for jid: wojtek@tigase.im/firefly/psi+/green
2019-08-12 17:37:40.436 [out_15-cl-comp]   SessionManager.getResourceConnection()  FINEST:   Found session: XMPPResourceConnection=[user_jid=wojtek@tigase.im/firefly/psi+/green, packets=143, connectioId=c2s@ip-10-0-28-108.us-west-2.compute.internal/10.0.28.108_5222_181.163.183.24_62651, domain=tigase.im, authState=AUTHORIZED, isAnon=false, isTmp=false, parentSession hash=1156623765, parentSession liveTime=58334], for jid: wojtek@tigase.im/firefly/psi+/green
2019-08-12 17:37:40.436 [out_15-cl-comp]   DefaultClusteringStrategyAbstract.sendToNextNode()  FINEST: Called for packet: from=null, to=null, DATA=<message type="chat" xmlns="jabber:client" xml:lang="en" to="wojtek@tigase.im/firefly/psi+/green" from="wojtek@jabster.pl/Psi+" id="wojtekDuplicateMessageTest4343"><body>CData size: 30</body></message>, SIZE=217, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=chat, visitedNodes: [sess-man@ip-10-0-12-136.us-west-2.compute.internal, sess-man@ip-10-0-28-108.us-west-2.compute.internal], result: false
2019-08-12 17:37:40.436 [out_15-cl-comp]   SessionManager.processPacket()          FINEST:   processing packet: from=s2s@ip-10-0-12-136.us-west-2.compute.internal, to=sess-man@ip-10-0-28-108.us-west-2.compute.internal, DATA=<message type="chat" xmlns="jabber:client" xml:lang="en" to="wojtek@tigase.im/firefly/psi+/green" from="wojtek@jabster.pl/Psi+" id="wojtekDuplicateMessageTest4343"><body>CData size: 30</body></message>, SIZE=217, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=chat, connection: XMPPResourceConnection=[user_jid=wojtek@tigase.im/firefly/psi+/green, packets=143, connectioId=c2s@ip-10-0-28-108.us-west-2.compute.internal/10.0.28.108_5222_181.163.183.24_62651, domain=tigase.im, authState=AUTHORIZED, isAnon=false, isTmp=false, parentSession hash=1156623765, parentSession liveTime=58334]

2019-08-12 17:37:40.437 [pool-36-thread-3]  ClusterConnectionManager.processSocketData()  FINEST: Processing socket data: from=null, to=null, DATA=<cluster type="set" xmlns="tigase:cluster" to="sess-man@ip-10-0-28-108.us-west-2.compute.internal" from="sess-man@ip-10-0-12-136.us-west-2.compute.internal" id="cl-3019819" pr="HIGH"><control><visited-nodes><node-id>CData size: 50</node-id></visited-nodes><method-call name="sess-man-packet-forward-sm-cmd"><par name="packet-from">CData size: 50</par></method-call><first-node>CData size: 50</first-node></control><data><message type="chat" xmlns="jabber:client" xml:lang="en" to="wojtek@tigase.im/firefly/psi+/green" from="wojtek@jabster.pl/Psi+" id="wojtekDuplicateMessageTest4343"><body>CData size: 30</body></message></data></cluster>, SIZE=762, XMLNS=tigase:cluster, PRIORITY=HIGH, PERMISSION=NONE, TYPE=set
2019-08-12 17:37:40.437 [pool-36-thread-3]  ClusterElement.<init>()                FINEST:   Parsing cluster element: <cluster type="set" xmlns="tigase:cluster" to="sess-man@ip-10-0-28-108.us-west-2.compute.internal" from="sess-man@ip-10-0-12-136.us-west-2.compute.internal" id="cl-3019819" pr="HIGH"><control><visited-nodes><node-id>sess-man@ip-10-0-12-136.us-west-2.compute.internal</node-id></visited-nodes><method-call name="sess-man-packet-forward-sm-cmd"><par name="packet-from">sess-man@ip-10-0-12-136.us-west-2.compute.internal</par></method-call><first-node>sess-man@ip-10-0-12-136.us-west-2.compute.internal</first-node></control><data><message type="chat" xmlns="jabber:client" xml:lang="en" to="wojtek@tigase.im/firefly/psi+/green" from="wojtek@jabster.pl/Psi+" id="wojtekDuplicateMessageTest4343"><body>wojtekDuplicateMessageTest4343</body></message></data></cluster>
2019-08-12 17:37:40.437 [pool-36-thread-3]  ClusterElement.<init>()                FINEST:   First node found: sess-man@ip-10-0-12-136.us-west-2.compute.internal
2019-08-12 17:37:40.437 [pool-36-thread-3]  ClusterElement.<init>()                FINEST:   Found and added visited nodes: 1
2019-08-12 17:37:40.437 [out_15-cl-comp]   ClusterElement.<init>()                 FINEST:   Parsing cluster element: <cluster type="set" xmlns="tigase:cluster" to="sess-man@ip-10-0-28-108.us-west-2.compute.internal" from="sess-man@ip-10-0-12-136.us-west-2.compute.internal" id="cl-3019819" pr="HIGH"><control><visited-nodes><node-id>sess-man@ip-10-0-12-136.us-west-2.compute.internal</node-id></visited-nodes><method-call name="sess-man-packet-forward-sm-cmd"><par name="packet-from">sess-man@ip-10-0-12-136.us-west-2.compute.internal</par></method-call><first-node>sess-man@ip-10-0-12-136.us-west-2.compute.internal</first-node></control><data><message type="chat" xmlns="jabber:client" xml:lang="en" to="wojtek@tigase.im/firefly/psi+/green" from="wojtek@jabster.pl/Psi+" id="wojtekDuplicateMessageTest4343"><body>wojtekDuplicateMessageTest4343</body></message></data></cluster>
2019-08-12 17:37:40.437 [out_15-cl-comp]   ClusterElement.<init>()                 FINEST:   First node found: sess-man@ip-10-0-12-136.us-west-2.compute.internal
2019-08-12 17:37:40.437 [out_15-cl-comp]   ClusterElement.<init>()                 FINEST:   Found and added visited nodes: 1
2019-08-12 17:37:40.437 [out_15-cl-comp]   PacketForwardCmd.executeCommand()       FINEST:   Called fromNode: sess-man@ip-10-0-12-136.us-west-2.compute.internal, visitedNodes: [sess-man@ip-10-0-12-136.us-west-2.compute.internal, sess-man@ip-10-0-28-108.us-west-2.compute.internal], data: {packet-from=sess-man@ip-10-0-12-136.us-west-2.compute.internal}, packets: [<message type="chat" xmlns="jabber:client" xml:lang="en" to="wojtek@tigase.im/firefly/psi+/green" from="wojtek@jabster.pl/Psi+" id="wojtekDuplicateMessageTest4343"><body>wojtekDuplicateMessageTest4343</body></message>]
2019-08-12 17:37:40.437 [out_15-cl-comp]   SessionManager.getXMPPResourceConnection()  FINEST: Searching for resource connection for: wojtek@tigase.im/firefly/psi+/green
2019-08-12 17:37:40.437 [out_15-cl-comp]   SessionManager.getResourceConnection()  FINEST:   Session not null, searching session for jid: wojtek@tigase.im/firefly/psi+/green
2019-08-12 17:37:40.438 [out_15-cl-comp]   SessionManager.getResourceConnection()  FINEST:   Found session: XMPPResourceConnection=[user_jid=wojtek@tigase.im/firefly/psi+/green, packets=144, connectioId=c2s@ip-10-0-28-108.us-west-2.compute.internal/10.0.28.108_5222_181.163.183.24_62651, domain=tigase.im, authState=AUTHORIZED, isAnon=false, isTmp=false, parentSession hash=1156623765, parentSession liveTime=58336], for jid: wojtek@tigase.im/firefly/psi+/green
2019-08-12 17:37:40.438 [out_15-cl-comp]   DefaultClusteringStrategyAbstract.sendToNextNode()  FINEST: Called for packet: from=null, to=null, DATA=<message type="chat" xmlns="jabber:client" xml:lang="en" to="wojtek@tigase.im/firefly/psi+/green" from="wojtek@jabster.pl/Psi+" id="wojtekDuplicateMessageTest4343"><body>CData size: 30</body></message>, SIZE=217, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=chat, visitedNodes: [sess-man@ip-10-0-12-136.us-west-2.compute.internal, sess-man@ip-10-0-28-108.us-west-2.compute.internal], result: false
2019-08-12 17:37:40.438 [out_15-cl-comp]   SessionManager.processPacket()          FINEST:   processing packet: from=sess-man@ip-10-0-12-136.us-west-2.compute.internal, to=sess-man@ip-10-0-28-108.us-west-2.compute.internal, DATA=<message type="chat" xmlns="jabber:client" xml:lang="en" to="wojtek@tigase.im/firefly/psi+/green" from="wojtek@jabster.pl/Psi+" id="wojtekDuplicateMessageTest4343"><body>CData size: 30</body></message>, SIZE=217, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=chat, connection: XMPPResourceConnection=[user_jid=wojtek@tigase.im/firefly/psi+/green, packets=144, connectioId=c2s@ip-10-0-28-108.us-west-2.compute.internal/10.0.28.108_5222_181.163.183.24_62651, domain=tigase.im, authState=AUTHORIZED, isAnon=false, isTmp=false, parentSession hash=1156623765, parentSession liveTime=58336]

Type	Bug
Priority	Normal
Assignee	Wojciech Kapcia (Tigase)
Spent time	1h

Issue Votes (0)

Watchers (0)

Reference

tigase/_server/server-core#1061