NPE in StreamManagementIOProcessor (#1188)

Wojciech Kapcia (Tigase) opened 5 years ago

[2020-08-14 17:49:09:732] [WARNING ] [ResultsListener-socketReadThread-7 ] SocketThread$ResultsListener.run(): Protocol execution exception.
java.lang.NullPointerException
	at tigase.server.xmppclient.StreamManagementIOProcessor$OutQueue$Entry.getPacketWithStamp(StreamManagementIOProcessor.java:689)
	at tigase.server.xmppclient.StreamManagementIOProcessor.sendErrorsForQueuedPackets(StreamManagementIOProcessor.java:575)
	at tigase.server.xmppclient.StreamManagementIOProcessor.serviceStopped(StreamManagementIOProcessor.java:456)
	at tigase.xmpp.XMPPIOService.forceStop(XMPPIOService.java:214)
	at tigase.net.IOService.stop(IOService.java:441)
	at tigase.xmpp.XMPPIOService.stop(XMPPIOService.java:261)
	at tigase.server.xmppclient.ClientConnectionManager.xmppStreamClosed(ClientConnectionManager.java:380)
	at tigase.server.xmppclient.ClientConnectionManager.serviceStopped(ClientConnectionManager.java:302)
	at tigase.server.xmppclient.StreamManagementIOProcessor.serviceStopped(StreamManagementIOProcessor.java:455)
	at tigase.xmpp.XMPPIOService.xmppStreamClosed(XMPPIOService.java:542)
	at tigase.xmpp.XMPPIOService.processSocketData(XMPPIOService.java:516)
	at tigase.net.IOService.call(IOService.java:200)
	at tigase.xmpp.XMPPIOService.call(XMPPIOService.java:146)
	at tigase.xmpp.XMPPIOService.call(XMPPIOService.java:51)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:834)

Possible diff?:

public Packet getPacketWithStamp() {
	Packet result = packet.copyElementOnly();
	if (result.getElemName() != Iq.ELEM_NAME && !result.isXMLNSStaticStr(DELAY_PATH, DELAY_XMLNS)) {
		String stamp = null;
		synchronized (formatter) {
			stamp = formatter.format(this.stamp);
		}
		String from = result.getStanzaTo() != null
					  ? result.getStanzaTo().getDomain()
-					  : result.getPacketTo().getDomain();
+					  : result.getPacketFrom().getDomain();

Wojciech Kapcia (Tigase) commented 5 years ago

Bigger log excerpt:

[2020-08-14 17:49:09:734] [FINEST  ] [ResultsListener-socketReadThread-7 ] SessionManager.processPacket(): processing packet: from=sess-man@ip-10-0-35-46.us-west-2.compute.internal, to=sess-man@ip-10-0-35-46.us-west-2.compute.internal, DATA=[message xmlns=&quot;jabber:client&quot; type=&quot;chat&quot; to=&quot;honeymoonsuitefan@tigase.im&quot; from=&quot;eric.teepell@tigase.im/phone&quot;][received id=&quot;bd4c6a89-7f1f-460a-b6c0-7832722768b6&quot; xmlns=&quot;urn:xmpp:chat-markers:0&quot;/][store xmlns=&quot;urn:xmpp:hints&quot;/][delay xmlns=&quot;urn:xmpp:delay&quot; stamp=&quot;2020-08-14T17:45:27.014Z&quot; from=&quot;tigase.im&quot;/][/message], SIZE=319, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=chat, STABLE_ID=3bd8d9a0-fed0-4ea1-890b-da603cb271a0, connection: null
[2020-08-14 17:49:09:732] [FINEST  ] [ResultsListener-socketReadThread-7 ] ClusterConnectionManager.processPacket(): Processing packet: from=null, to=null, DATA=[cluster id=&quot;cl-80398&quot; type=&quot;set&quot; xmlns=&quot;tigase:cluster&quot; to=&quot;sess-man@ip-10-0-9-172.us-west-2.compute.internal&quot; pr=&quot;CLUSTER&quot; from=&quot;sess-man@ip-10-0-35-46.us-west-2.compute.internal&quot;][control][visited-nodes][node-id]CData size: 49[/node-id][/visited-nodes][method-call name=&quot;sess-man-user-disconnected-sm-cmd&quot;][par name=&quot;userId&quot;]CData size: 27[/par][par name=&quot;resource&quot;]CData size: 5[/par][par name=&quot;connId&quot;]CData size: 79[/par][par name=&quot;xmppSessId&quot;]CData size: 36[/par][par name=&quot;auth-time&quot;]CData size: 3[/par][par name=&quot;creation-t&quot;]CData size: 13[/par][par name=&quot;login_t&quot;]CData size: 3[/par][/method-call][first-node]CData size: 49[/first-node][/control][/cluster], SIZE=807, XMLNS=tigase:cluster, PRIORITY=CLUSTER, PERMISSION=NONE, TYPE=set, STABLE_ID=null
[2020-08-14 17:49:09:734] [FINEST  ] [ResultsListener-socketReadThread-7 ] ClusterElement.[init](): Parsing cluster element: [cluster id=&quot;cl-80398&quot; type=&quot;set&quot; xmlns=&quot;tigase:cluster&quot; to=&quot;sess-man@ip-10-0-9-172.us-west-2.compute.internal&quot; pr=&quot;CLUSTER&quot; from=&quot;sess-man@ip-10-0-35-46.us-west-2.compute.internal&quot;][control][visited-nodes][node-id]sess-man@ip-10-0-35-46.us-west-2.compute.internal[/node-id][/visited-nodes][method-call name=&quot;sess-man-user-disconnected-sm-cmd&quot;][par name=&quot;userId&quot;]honeymoonsuitefan@tigase.im[/par][par name=&quot;resource&quot;]phone[/par][par name=&quot;connId&quot;]c2s@ip-10-0-35-46.us-west-2.compute.internal/10.0.35.46_5223_23.92.128.64_51178[/par][par name=&quot;xmppSessId&quot;]46252bbe-7949-4a79-889d-ce1d262dd8d6[/par][par name=&quot;auth-time&quot;]229[/par][par name=&quot;creation-t&quot;]1597427167157[/par][par name=&quot;login_t&quot;]229[/par][/method-call][first-node]sess-man@ip-10-0-35-46.us-west-2.compute.internal[/first-node][/control][/cluster]
[2020-08-14 17:49:09:734] [FINEST  ] [ResultsListener-socketReadThread-7 ] ClusterElement.[init](): First node found: sess-man@ip-10-0-35-46.us-west-2.compute.internal
[2020-08-14 17:49:09:734] [FINEST  ] [ResultsListener-socketReadThread-7 ] ClusterElement.[init](): Found and added visited nodes: 1
[2020-08-14 17:49:09:734] [FINEST  ] [ResultsListener-socketReadThread-7 ] ConnectionManager.writePacketToSocket(): null, type: connect, Socket: nullSocket[addr=ip-10-0-9-172.us-west-2.compute.internal/10.0.9.172,port=5277,localport=52720], jid: ip-10-0-9-172.us-west-2.compute.internal, Writing packet: from=null, to=null, DATA=[cluster id=&quot;cl-80398&quot; type=&quot;set&quot; xmlns=&quot;tigase:cluster&quot; to=&quot;sess-man@ip-10-0-9-172.us-west-2.compute.internal&quot; pr=&quot;CLUSTER&quot; from=&quot;sess-man@ip-10-0-35-46.us-west-2.compute.internal&quot;][control][visited-nodes][node-id]CData size: 49[/node-id][/visited-nodes][method-call name=&quot;sess-man-user-disconnected-sm-cmd&quot;][par name=&quot;userId&quot;]CData size: 27[/par][par name=&quot;resource&quot;]CData size: 5[/par][par name=&quot;connId&quot;]CData size: 79[/par][par name=&quot;xmppSessId&quot;]CData size: 36[/par][par name=&quot;auth-time&quot;]CData size: 3[/par][par name=&quot;creation-t&quot;]CData size: 13[/par][par name=&quot;login_t&quot;]CData size: 3[/par][/method-call][first-node]CData size: 49[/first-node][/control][/cluster], SIZE=807, XMLNS=tigase:cluster, PRIORITY=CLUSTER, PERMISSION=NONE, TYPE=set, STABLE_ID=null
[2020-08-14 17:49:09:734] [FINEST  ] [ResultsListener-socketReadThread-7 ] XMPPIOService.processWaitingPackets(): null, type: connect, Socket: nullSocket[addr=ip-10-0-9-172.us-west-2.compute.internal/10.0.9.172,port=5277,localport=52720], jid: ip-10-0-9-172.us-west-2.compute.internal, Sending packet: from=null, to=null, DATA=[cluster id=&quot;cl-80398&quot; type=&quot;set&quot; xmlns=&quot;tigase:cluster&quot; to=&quot;sess-man@ip-10-0-9-172.us-west-2.compute.internal&quot; pr=&quot;CLUSTER&quot; from=&quot;sess-man@ip-10-0-35-46.us-west-2.compute.internal&quot;][control][visited-nodes][node-id]CData size: 49[/node-id][/visited-nodes][method-call name=&quot;sess-man-user-disconnected-sm-cmd&quot;][par name=&quot;userId&quot;]CData size: 27[/par][par name=&quot;resource&quot;]CData size: 5[/par][par name=&quot;connId&quot;]CData size: 79[/par][par name=&quot;xmppSessId&quot;]CData size: 36[/par][par name=&quot;auth-time&quot;]CData size: 3[/par][par name=&quot;creation-t&quot;]CData size: 13[/par][par name=&quot;login_t&quot;]CData size: 3[/par][/method-call][first-node]CData size: 49[/first-node][/control][/cluster], SIZE=807, XMLNS=tigase:cluster, PRIORITY=CLUSTER, PERMISSION=NONE, TYPE=set, STABLE_ID=null
[2020-08-14 17:49:09:734] [FINEST  ] [ResultsListener-socketReadThread-7 ] XMPPIOService.processWaitingPackets(): null, type: connect, Socket: nullSocket[addr=ip-10-0-9-172.us-west-2.compute.internal/10.0.9.172,port=5277,localport=52720], jid: ip-10-0-9-172.us-west-2.compute.internal, SENT: [cluster id=&quot;cl-80398&quot; type=&quot;set&quot; xmlns=&quot;tigase:cluster&quot; to=&quot;sess-man@ip-10-0-9-172.us-west-2.compute.internal&quot; pr=&quot;CLUSTER&quot; from=&quot;sess-man@ip-10-0-35-46.us-west-2.compute.internal&quot;][control][visited-nodes][node-id]sess-man@ip-10-0-35-46.us-west-2.compute.internal[/node-id][/visited-nodes][method-call name=&quot;sess-man-user-disconnected-sm-cmd&quot;][par name=&quot;userId&quot;]honeymoonsuitefan@tigase.im[/par][par name=&quot;resource&quot;]phone[/par][par name=&quot;connId&quot;]c2s@ip-10-0-35-46.us-west-2.compute.internal/10.0.35.46_5223_23.92.128.64_51178[/par][par name=&quot;xmppSessId&quot;]46252bbe-7949-4a79-889d-ce1d262dd8d6[/par][par name=&quot;auth-time&quot;]229[/par][par name=&quot;creation-t&quot;]1597427167157[/par][par name=&quot;login_t&quot;]229[/par][/method-call][first-node]sess-man@ip-10-0-35-46.us-west-2.compute.internal[/first-node][/control][/cluster]
[2020-08-14 17:49:09:733] [FINEST  ] [ResultsListener-socketReadThread-7 ] DomainFilter.filter(): Filtering (packet): from=null, to=sess-man@ip-10-0-35-46.us-west-2.compute.internal, DATA=[message xmlns=&quot;jabber:client&quot; type=&quot;chat&quot; to=&quot;honeymoonsuitefan@tigase.im/phone&quot; from=&quot;eric.teepell@tigase.im/phone&quot;][received id=&quot;bd4c6a89-7f1f-460a-b6c0-7832722768b6&quot; xmlns=&quot;urn:xmpp:chat-markers:0&quot;/][store xmlns=&quot;urn:xmpp:hints&quot;/][delay xmlns=&quot;urn:xmpp:delay&quot; stamp=&quot;2020-08-14T17:45:27.014Z&quot; from=&quot;tigase.im&quot;/][delivery-error stamp=&quot;1597427204146&quot; xmlns=&quot;http://tigase.org/delivery-error&quot;/][/message], SIZE=405, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=chat, STABLE_ID=3bd8d9a0-fed0-4ea1-890b-da603cb271a0
[2020-08-14 17:49:09:734] [FINER   ] [ResultsListener-socketReadThread-7 ] StanzaProcessor.process(): Handled by module class tigase.pubsub.modules.PresenceCollectorModule
[2020-08-14 17:49:09:732] [WARNING ] [ResultsListener-socketReadThread-7 ] SocketThread$ResultsListener.run(): Protocol execution exception.
java.lang.NullPointerException
	at tigase.server.xmppclient.StreamManagementIOProcessor$OutQueue$Entry.getPacketWithStamp(StreamManagementIOProcessor.java:689)
	at tigase.server.xmppclient.StreamManagementIOProcessor.sendErrorsForQueuedPackets(StreamManagementIOProcessor.java:575)
	at tigase.server.xmppclient.StreamManagementIOProcessor.serviceStopped(StreamManagementIOProcessor.java:456)
	at tigase.xmpp.XMPPIOService.forceStop(XMPPIOService.java:214)
	at tigase.net.IOService.stop(IOService.java:441)
	at tigase.xmpp.XMPPIOService.stop(XMPPIOService.java:261)
	at tigase.server.xmppclient.ClientConnectionManager.xmppStreamClosed(ClientConnectionManager.java:380)
	at tigase.server.xmppclient.ClientConnectionManager.serviceStopped(ClientConnectionManager.java:302)
	at tigase.server.xmppclient.StreamManagementIOProcessor.serviceStopped(StreamManagementIOProcessor.java:455)
	at tigase.xmpp.XMPPIOService.xmppStreamClosed(XMPPIOService.java:542)
	at tigase.xmpp.XMPPIOService.processSocketData(XMPPIOService.java:516)
	at tigase.net.IOService.call(IOService.java:200)
	at tigase.xmpp.XMPPIOService.call(XMPPIOService.java:146)
	at tigase.xmpp.XMPPIOService.call(XMPPIOService.java:51)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:834)

Andrzej Wójcik (Tigase) commented 5 years ago

from in this case should be just a users jid bare domain, so while usage of stanzaTo and packetTo looks ok, then usage of packetFrom somehow doesn't look ok for me.

I wonder, what actually was there and why it didn't have packetTo set. AFAIR, only packets with packetTo are sent to the client connection and without it should be sent to sess-man for processing? Either way, I would like to know what actually happened (what packet was that) or we could adding domain jid while adding packet to the queue of packets waiting for confirmation (there should be a user JID which could be retrieved from XMPPIOService if I'm correct)

@wojtek What do you think?

Wojciech Kapcia (Tigase) commented 5 years ago

It happened again, or at least it seems so (logs so visibility is limited)

[2020-08-15 16:17:54:061] [FINEST  ] [              in_2-c2s ] MessageRouter.processPacket()    : 1. Packet will be processed by: c2s@ip-10-0-9-172.us-west-2.compute.internal, from=sess-man@ip-10-0-9-172.us-west-2.compute.internal, to=c2s@ip-10-0-9-172.us-west-2.compute.internal/10.0.9.172_5223_162.247.73.193_47882, DATA=[iq type=&quot;result&quot; id=&quot;9cd2baf5-6d8f-4113-ac66-999203ccca11&quot; from=&quot;sess-man@ip-10-0-9-172.us-west-2.compute.internal&quot; to=&quot;c2s@ip-10-0-9-172.us-west-2.compute.internal/10.0.9.172_5223_162.247.73.193_47882&quot;/], SIZE=205, XMLNS=null, PRIORITY=SYSTEM, PERMISSION=NONE, TYPE=result, STABLE_ID=null
[2020-08-15 16:17:54:060] [FINER   ] [              in_2-c2s ] SessionManager.closeConnection() : Stream closed from: c2s@ip-10-0-9-172.us-west-2.compute.internal/10.0.9.172_5223_162.247.73.193_47882
[2020-08-15 16:17:54:061] [SEVERE  ] [              in_2-c2s ] AbstractMessageReceiver$QueueListener.run(): [in_2-c2s] Exception during packet processing: from=sess-man@ip-10-0-9-172.us-west-2.compute.internal, to=c2s@ip-10-0-9-172.us-west-2.compute.internal/10.0.9.172_5223_162.247.73.193_47882, DATA=[iq type=&quot;set&quot; from=&quot;sess-man@ip-10-0-9-172.us-west-2.compute.internal&quot; id=&quot;tig3&quot; to=&quot;c2s@ip-10-0-9-172.us-west-2.compute.internal/10.0.9.172_5223_162.247.73.193_47882&quot;][command xmlns=&quot;http://jabber.org/protocol/commands&quot; node=&quot;CLOSE&quot;][conflict xmlns=&quot;urn:ietf:params:xml:ns:xmpp-streams&quot;/][/command][/iq], SIZE=305, XMLNS=null, PRIORITY=SYSTEM, PERMISSION=NONE, TYPE=set, STABLE_ID=null
java.lang.NullPointerException
	at tigase.server.xmppclient.StreamManagementIOProcessor$OutQueue$Entry.getPacketWithStamp(StreamManagementIOProcessor.java:689)
	at tigase.server.xmppclient.StreamManagementIOProcessor.sendErrorsForQueuedPackets(StreamManagementIOProcessor.java:575)
	at tigase.server.xmppclient.StreamManagementIOProcessor.serviceStopped(StreamManagementIOProcessor.java:407)
	at tigase.xmpp.XMPPIOService.forceStop(XMPPIOService.java:214)
	at tigase.net.IOService.stop(IOService.java:441)
	at tigase.xmpp.XMPPIOService.stop(XMPPIOService.java:261)
	at tigase.server.xmppclient.ClientConnectionManager.xmppStreamClosed(ClientConnectionManager.java:380)
	at tigase.server.xmppclient.ClientConnectionManager.serviceStopped(ClientConnectionManager.java:302)
	at tigase.server.xmppclient.StreamManagementIOProcessor.serviceStopped(StreamManagementIOProcessor.java:406)
	at tigase.xmpp.XMPPIOService.forceStop(XMPPIOService.java:214)
	at tigase.net.IOService.stop(IOService.java:441)
	at tigase.xmpp.XMPPIOService.stop(XMPPIOService.java:261)
	at tigase.server.xmppclient.ClientConnectionManager.processCommand(ClientConnectionManager.java:837)
	at tigase.server.xmppclient.ClientConnectionManager.processPacket(ClientConnectionManager.java:129)
	at tigase.server.AbstractMessageReceiver$QueueListener.run(AbstractMessageReceiver.java:1405)

[2020-08-15 16:19:58:836] [SEVERE  ] [              in_1-c2s ] AbstractMessageReceiver$QueueListener.run(): [in_1-c2s] Exception during packet processing: from=sess-man@ip-10-0-35-46.us-west-2.compute.internal, to=c2s@ip-10-0-35-46.us-west-2.compute.internal/10.0.35.46_5223_162.247.73.193_38896, DATA=[iq id=&quot;moved&quot; type=&quot;set&quot; to=&quot;c2s@ip-10-0-35-46.us-west-2.compute.internal/10.0.35.46_5223_162.247.73.193_38896&quot; from=&quot;sess-man@ip-10-0-35-46.us-west-2.compute.internal&quot;][command node=&quot;STREAM_MOVED&quot; xmlns=&quot;http://jabber.org/protocol/commands&quot;][x type=&quot;submit&quot; xmlns=&quot;jabber:x:data&quot;][field var=&quot;cmd&quot;][value]CData size: 12[/value][/field][field var=&quot;new-conn-jid&quot;][value]CData size: 79[/value][/field][/x][/command][/iq], SIZE=481, XMLNS=null, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=set, STABLE_ID=null
java.lang.NullPointerException
	at tigase.server.xmppclient.StreamManagementIOProcessor$OutQueue$Entry.getPacketWithStamp(StreamManagementIOProcessor.java:689)
	at tigase.server.xmppclient.StreamManagementIOProcessor.processCommand(StreamManagementIOProcessor.java:299)
	at tigase.server.xmppclient.ClientConnectionManager.processCommand(ClientConnectionManager.java:871)
	at tigase.server.xmppclient.ClientConnectionManager.processPacket(ClientConnectionManager.java:129)
	at tigase.server.AbstractMessageReceiver$QueueListener.run(AbstractMessageReceiver.java:1405)

west-2.compute.internal/10.0.9.172_5222_160.32.222.227_52713
[2020-08-16 04:12:14:664] [FINEST  ] [              in_4-c2s ] SessionManagerClustered.processPacket(): Received packet: from=c2s@ip-10-0-9-172.us-west-2.compute.internal/10.0.9.172_5222_160.32.222.227_52713, to=sess-man@ip-10-0-9-172.us-west-2.compute.internal, DATA=[iq from=&quot;c2s@ip-10-0-9-172.us-west-2.compute.internal/10.0.9.172_5222_160.32.222.227_52713&quot; delay=&quot;120&quot; type=&quot;set&quot; id=&quot;a1ab7f33-f900-4a28-a2c8-049161597061&quot; to=&quot;sess-man@ip-10-0-9-172.us-west-2.compute.internal&quot; retryCount=&quot;15&quot;][command xmlns=&quot;http://jabber.org/protocol/commands&quot; node=&quot;STREAM_CLOSED&quot;][x type=&quot;submit&quot; xmlns=&quot;jabber:x:data&quot;][field var=&quot;user-jid&quot;][value]CData size: 26[/value][/field][/x][/command][/iq], SIZE=432, XMLNS=null, PRIORITY=SYSTEM, PERMISSION=NONE, TYPE=set, STABLE_ID=null
[2020-08-16 04:12:14:665] [WARNING ] [              in_4-c2s ] ConnectionManager.writePacketToSocket(): c2s@ip-10-0-9-172.us-west-2.compute.internal/10.0.9.172_5222_160.32.222.227_52713, type: accept, Socket: TLS: c2s@ip-10-0-9-172.us-west-2.compute.internal/10.0.9.172_5222_160.32.222.227_52713 Socket[unconnected], jid: mgao@sure.im/Mike’s iPhoneException during writing packets: 
java.lang.NullPointerException
	at tigase.server.xmppclient.StreamManagementIOProcessor$OutQueue$Entry.getPacketWithStamp(StreamManagementIOProcessor.java:689)
	at tigase.server.xmppclient.StreamManagementIOProcessor.sendErrorsForQueuedPackets(StreamManagementIOProcessor.java:575)
	at tigase.server.xmppclient.StreamManagementIOProcessor.serviceStopped(StreamManagementIOProcessor.java:394)
	at tigase.xmpp.XMPPIOService.forceStop(XMPPIOService.java:214)

Wojciech Kapcia (Tigase) commented 5 years ago

I'm not sure that packets from the logs are indeed responsible. I agree it would be good to capture the exact stanza that causes the issue.
Andrzej Wójcik (Tigase) commented 5 years ago

should we modify source code that if NPE is thrown we would catch it and log stanza which caused it?
Andrzej Wójcik (Tigase) commented 5 years ago

I've looked into the code and decided to log those packets (if logging would be set to FINEST) and to deal with NPE by using DNSResolverIfc::getDefaultHost() if stanzaTo is NULL and packetTo is NULL (if I'm correct packetTo is actually default hostname of a node, so that would work just fine).

If we would catch those entries (stanzas causing the issue) we may decide to adjust this workaround.
Wojciech Kapcia (Tigase) commented 5 years ago

Fix seems sensible. One "but", with the changed code we won't receive any notifications - given it's temporary, maybe we should use WARNING level (and after verifying it change it to something more adequate or remove altogether)?
Andrzej Wójcik (Tigase) commented 5 years ago

I'm not sure if this change will be temporary as I do not know which stanza is actually causing the issue. Using default host is a good fix even for a long term and if/when we want to check what is causing this issue we can just change logging level for this class and then check logs.
Wojciech Kapcia (Tigase) commented 5 years ago

My comment about 'temporary' nature was more about logging those packets explicitly. Basically, currently with FINEST those entries will end-up in the logs (we have quite verbose logging on our installations) but... we won't receive any notification (mailer is only for WARNING and higher). I'd say we won't be checking those logs manually/periodically to see if by any chance there was an issue and which packet caused it. Changing the log level to WARNING (for now, until 8.2.0 final version) would give us opportunity to monitor the issue and have notifications when it happens (so it would be adjusted if needed).
Wojciech Kapcia (Tigase) commented 5 years ago

OK, I wrongly assumed that new "missing TO" entries were related to other issue (#issue #1075: https://projects.tigase.net/issue/issue #1075#focus=Comments-4-27110.0-0)

They seems to be presence packets only.

Wojciech Kapcia (Tigase) commented 5 years ago

[2020-08-28 17:50:46:698] [WARNING ] [scheduler_pool-15-thread-2-c2s ] StreamManagementIOProcessor$OutQueue$Entry.getPacketWithStamp(): unacked packet without &apos;stanzaTo&apos; and &apos;packetTo&apos; from=sess-man@ip-10-0-7-38.us-west-2.compute.internal, to=c2s@ip-10-0-19-100.us-west-2.compute.internal/10.0.19.100_5223_199.119.232.215_42269, DATA=[presence xmlns=&quot;jabber:client&quot; from=&quot;honeymoonsuitefan@tigase.im/phone&quot;][c ver=&quot;J4DkJOCHg8pwLcq6fqA2HW5Z3S0=&quot; xmlns=&quot;http://jabber.org/protocol/caps&quot; node=&quot;http://conversations.im&quot; hash=&quot;sha-1&quot;/][x xmlns=&quot;vcard-temp:x:update&quot;][photo]CData size: 40[/photo][/x][/presence], SIZE=297, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null
[2020-08-28 17:50:46:698] [WARNING ] [scheduler_pool-15-thread-2-c2s ] StreamManagementIOProcessor$OutQueue$Entry.getPacketWithStamp(): unacked packet without &apos;stanzaTo&apos; and &apos;packetTo&apos; from=sess-man@ip-10-0-7-38.us-west-2.compute.internal, to=c2s@ip-10-0-19-100.us-west-2.compute.internal/10.0.19.100_5223_199.119.232.215_42269, DATA=[presence xmlns=&quot;jabber:client&quot; from=&quot;honeymoonsuitefan@tigase.im/phone&quot;][c ver=&quot;J4DkJOCHg8pwLcq6fqA2HW5Z3S0=&quot; xmlns=&quot;http://jabber.org/protocol/caps&quot; node=&quot;http://conversations.im&quot; hash=&quot;sha-1&quot;/][x xmlns=&quot;vcard-temp:x:update&quot;][photo]CData size: 40[/photo][/x][/presence], SIZE=297, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null
[2020-08-28 17:50:46:706] [WARNING ] [scheduler_pool-15-thread-2-c2s ] StreamManagementIOProcessor$OutQueue$Entry.getPacketWithStamp(): unacked packet without &apos;stanzaTo&apos; and &apos;packetTo&apos; from=sess-man@ip-10-0-19-100.us-west-2.compute.internal, to=c2s@ip-10-0-19-100.us-west-2.compute.internal/10.0.19.100_5223_199.119.232.215_42269, DATA=[presence type="unavailable" xmlns="jabber:client" from="honeymoonsuitefan@tigase.im/phone"][c ver="J4DkJOCHg8pwLcq6fqA2HW5Z3S0=" xmlns="http://jabber.org/protocol/caps" node="http://conversations.im" hash="sha-1"/][x xmlns="vcard-temp:x:update"][photo]CData size: 40[/photo][/x][/presence], SIZE=316, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=unavailable, STABLE_ID=null
[2020-08-28 17:50:46:723] [WARNING ] [scheduler_pool-15-thread-2-c2s ] StreamManagementIOProcessor$OutQueue$Entry.getPacketWithStamp(): unacked packet without &apos;stanzaTo&apos; and &apos;packetTo&apos; from=sess-man@ip-10-0-19-100.us-west-2.compute.internal, to=c2s@ip-10-0-19-100.us-west-2.compute.internal/10.0.19.100_5223_199.119.232.215_42269, DATA=[presence xmlns="jabber:client" from="honeymoonsuitefan@tigase.im/phone"][c ver="J4DkJOCHg8pwLcq6fqA2HW5Z3S0=" xmlns="http://jabber.org/protocol/caps" node="http://conversations.im" hash="sha-1"/][/presence], SIZE=207, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null
[2020-08-28 19:57:27:676] [WARNING ] [      pool-33-thread-5 ] StreamManagementIOProcessor$OutQueue$Entry.getPacketWithStamp(): unacked packet without &apos;stanzaTo&apos; and &apos;packetTo&apos; from=sess-man@ip-10-0-19-100.us-west-2.compute.internal, to=c2s@ip-10-0-19-100.us-west-2.compute.internal/10.0.19.100_5223_76.68.100.171_40258, DATA=[presence type="unavailable" xmlns="jabber:client" from="eric.teepell@tigase.im/Conversations.j_YE"][c ver="zcIke+Rk13ah4d1pwDG7bEZsVwA=" xmlns="http://jabber.org/protocol/caps" node="http://conversations.im" hash="sha-1"/][x xmlns="vcard-temp:x:update"][photo]CData size: 40[/photo][/x][/presence], SIZE=324, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=unavailable, STABLE_ID=null
[2020-08-28 20:34:48:761] [WARNING ] [scheduler_pool-15-thread-1-c2s ] StreamManagementIOProcessor$OutQueue$Entry.getPacketWithStamp(): unacked packet without &apos;stanzaTo&apos; and &apos;packetTo&apos; from=sess-man@ip-10-0-7-38.us-west-2.compute.internal, to=c2s@ip-10-0-7-38.us-west-2.compute.internal/10.0.7.38_5223_199.119.232.209_42964, DATA=[presence from="eric.teepell@tigase.im/Conversations.j_YE" xmlns="jabber:client"][c hash="sha-1" node="http://conversations.im" ver="zcIke+Rk13ah4d1pwDG7bEZsVwA=" xmlns="http://jabber.org/protocol/caps"/][/presence], SIZE=215, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null
[2020-08-28 20:48:00:754] [WARNING ] [scheduler_pool-15-thread-1-c2s ] StreamManagementIOProcessor$OutQueue$Entry.getPacketWithStamp(): unacked packet without &apos;stanzaTo&apos; and &apos;packetTo&apos; from=sess-man@ip-10-0-7-38.us-west-2.compute.internal, to=c2s@ip-10-0-32-126.us-west-2.compute.internal/10.0.32.126_5223_198.96.155.3_59167, DATA=[presence from="eric.teepell@tigase.im/gajim.IBE78F8H" xmlns="jabber:client" id="0de6742f-9858-4293-8f89-e4c2c59f7bb8"][priority]50[/priority][c node="http://gajim.org" xmlns="http://jabber.org/protocol/caps" hash="sha-1" ver="KV4qaXUgvEqhWE7WEJoqvO6gTYA="/][x xmlns="vcard-temp:x:update"][photo]CData size: 40[/photo][/x][/presence], SIZE=359, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null

Wojciech Kapcia (Tigase) commented 5 years ago
Considering the payload few comments come to mind:

this is a presence to closed connection (streams are being closed just before those entries) - but it seems to be incomming presence from that connection, yet packet originates from SessMann.

in that case, volatile presence are not that important here (and could be dropped?)

we still should stamp all stanzas with appropriate to/from if we are generating them - seems like a bug in Presence plugin in this case?
Andrzej Wójcik (Tigase) commented 5 years ago

PresenceState::updateUserResources() method has proper setting from and to attributes of a generated presences to other resources of the same user, so this is not an issue in the Presence processor.

As I've looked at OutQueue::getPacketWithStamp() method, I've found that latest modification of this code is actually causing the issue. Instead of checking if original packet has stanzaFrom or packetFrom, it checked result packet generated with copyElementOnly() which could not have packetFrom set.

I've fixed this error in the code and that should solve the issue.

Wojciech Kapcia (Tigase) commented 5 years ago

PresenceState::updateUserResources() method has proper setting from and to attributes of a generated presences to other resources of the same user, so this is not an issue in the Presence processor.

There is something generating those packets without to (they seem to originate from sess-man). Unfortunately logs in notification doesn't have anything relevant and those on the instances were already rotated.

As I've looked at OutQueue::getPacketWithStamp() method, I've found that latest modification of this code is actually causing the issue. Instead of checking if original packet has stanzaFrom or packetFrom, it checked result packet generated with copyElementOnly() which could not have packetFrom set.

It seems that result was used even before so in the end it was a good call to leave the debugging to catch it.

At any rate - the issue was still happening even after update (version from 4th of September) and packets seemingly containing correct addressing:

[2020-09-02 00:32:06:591] [WARNING ] [scheduler_pool-15-thread-1-c2s ] StreamManagementIOProcessor$OutQueue$Entry.getPacketWithStamp(): unacked packet without &apos;stanzaTo&apos; and &apos;packetTo&apos; from=sess-man@ip-10-0-19-100.us-west-2.compute.internal, to=c2s@ip-10-0-19-100.us-west-2.compute.internal/10.0.19.100_5223_75.119.241.105_52774, DATA=[presence from="…@tigase.im/phone" xmlns="jabber:client"][c ver="J4DkJOCHg8pwLcq6fqA2HW5Z3S0=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/][/presence], SIZE=207, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null
[2020-09-02 23:40:43:267] [WARNING ] [scheduler_pool-15-thread-1-c2s ] StreamManagementIOProcessor$OutQueue$Entry.getPacketWithStamp(): unacked packet without &apos;stanzaTo&apos; and &apos;packetTo&apos; from=sess-man@ip-10-0-7-38.us-west-2.compute.internal, to=c2s@ip-10-0-7-38.us-west-2.compute.internal/10.0.7.38_5223_75.119.241.105_49838, DATA=[presence from="…@tigase.im/phone" xmlns="jabber:client"][c hash="sha-1" node="http://conversations.im" ver="J4DkJOCHg8pwLcq6fqA2HW5Z3S0=" xmlns="http://jabber.org/protocol/caps"/][/presence], SIZE=207, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null
[2020-09-03 00:26:37:973] [WARNING ] [scheduler_pool-15-thread-2-c2s ] StreamManagementIOProcessor$OutQueue$Entry.getPacketWithStamp(): unacked packet without &apos;stanzaTo&apos; and &apos;packetTo&apos; from=sess-man@ip-10-0-32-126.us-west-2.compute.internal, to=c2s@ip-10-0-32-126.us-west-2.compute.internal/10.0.32.126_5223_75.119.241.105_50148, DATA=[presence from="…@tigase.im/phone" xmlns="jabber:client"][c node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1" ver="J4DkJOCHg8pwLcq6fqA2HW5Z3S0="/][/presence], SIZE=207, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null

I slightly adjusted log entry and will monitor.

Wojciech Kapcia (Tigase) commented 5 years ago

There were two more cases with evidently missing "to" (packet and stanza).

[2020-09-09 00:38:25:169] [WARNING ] [      pool-31-thread-7 ] StreamManagementIOProcessor$OutQueue$Entry.getPacketWithStamp(): unacked packet without stanzaTo: null, and packetTo: null; setting from to: ip-10-0-19-218.us-west-2.compute.internal; packet: from=null, to=null, DATA=[presence from="…@sure.im/137942851-tigase-800" xmlns="jabber:client" type="unavailable"][show]CData size: 4[/show][status]CData size: 27[/status][c hash="sha-1" xmlns="http://jabber.org/protocol/caps" node="http://pidgin.im/" ver="idag4kq0P9//LxPEfum0+nqUnhU="/][x xmlns="vcard-temp:x:update"/][delay xmlns="urn:xmpp:delay" from="ip-10-0-19-218.us-west-2.compute.internal" stamp="2020-09-09T00:38:14.792Z"/][/presence], SIZE=428, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=unavailable, STABLE_ID=null
[2020-09-10 03:14:51:485] [WARNING ] [              in_4-c2s ] StreamManagementIOProcessor$OutQueue$Entry.getPacketWithStamp(): unacked packet without stanzaTo: null, and packetTo: null; setting from to: ip-10-0-15-235.us-west-2.compute.internal; packet: from=null, to=null, DATA=[presence from="…@sure.im/Conv6ations.1pxU" type="unavailable" xmlns="jabber:client"][c ver="UImjMKW4pS3Y9uK7Pr42dijbsXs=" hash="sha-1" node="http://jabber.pix-art.de" xmlns="http://jabber.org/protocol/caps"/][idle since="2020-09-09T22:25:13.827Z" xmlns="urn:xmpp:idle:1"/][x xmlns="vcard-temp:x:update"][photo]CData size: 40[/photo][/x][delay stamp="2020-09-10T03:12:15.739Z" from="ip-10-0-15-235.us-west-2.compute.internal" xmlns="urn:xmpp:delay"/][/presence], SIZE=494, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=unavailable, STABLE_ID=null

I'm not sure that using from = DNSResolverFactory.getInstance().getDefaultHost(); in this case will solve it - packet would be redirected back to SessionManager which would expect from in a form of c2s@ip-10-0-19-100.us-west-2.compute.internal/10.0.19.100_5223_75.119.241.105_52774 (i.e. connectionID) to correctly find possible matching session.

Still, it does seem that those presence packets should have full from/to.

Andrzej Wójcik (Tigase) commented 5 years ago

Are those presences even valid? Shouldn't they be processed by SM and to should be set or they should be dropped? AFAIR, presence without to is possible to be sent to the server only to set resource presence and then it is handled by the server. Here, we do have a presence without a to but with a from and always with type=unavailable, so it looks like a client is sending presence unavailable and then just disconnecting without waiting for a result and server is processing STREAM_CLOSE before this presence is processed leading to sending it back to the clients connection which times out?
Wojciech Kapcia (Tigase) commented 5 years ago

@andrzej.wojcik It looks like that, but didn't we have mechanism that informs SM about stream closure but would allow processing of the incoming stanzas as if session was still open?
Andrzej Wójcik (Tigase) commented 5 years ago

Well, we do have a code which sends STREAM_FINISHED after sending all packets from the connection manager to the SM with PRIORITY set to NORMAL, but then if SM would reply on those presences (sent them back), they would be queued on the closed connection StreamManagement queue if that connection is not closed before delivering those packets back to the connection manager.

In this case, presence would be router back to the connection (as session was already closed?) and it delivers before confirmation of session close to the connection manager. Is that possible?
Wojciech Kapcia (Tigase) commented 5 years ago

It does seem impossible. Though, generated packets should still have proper addressing - maybe it's worth quickly checking out this as well?

I'd lean towards dropping those packets - they are invalid, it's impossible to deliver them and they would be dropped later on either way.
Andrzej Wójcik (Tigase) commented 5 years ago

@wojtek Before I'll disable this questionable workaround, I've checked the code for possible sources of a presence without to attribute. I've pinpointed it be sent by SessionManager but in ACS mode. When client connection gets disconnected, cluster node to which it was connected broadcasts to other cluster nodes presence with from but without to attribute. If there is any other connection for the same bare jid on any other cluster node, then it sends it to that connection but it sets only packetTo, so we end up with presence without to being set.

I suppose that we may drop those packets, or maybe we should enforce setting to in the SM-ACS?

I would suggest to "fix ACS" (add to to generated packets) and then recheck if that issue is fixed and if so then close this task.
Andrzej Wójcik (Tigase) commented 5 years ago
According to the RFC6121, section 4.5.2. Server Processing of Outbound Unavailable Presence:

The user's server MUST also send the unavailable notification to all of the user's available resources (as well as to the resource that generated the unavailable presence in the first place).

<presence from='juliet@example.com/balcony' to='juliet@example.com/chamber' type='unavailable'> <status>going on vacation</status> </presence>

Looking at this example (non-normative I suppose) we do see that it has from and to set and I would suggest to handle it in the same way in Tigase.
Andrzej Wójcik (Tigase) commented 5 years ago

The code was adjusted in default clustering and in ACS to include to attribute in presence packet delivered from other cluster node.
Wojciech Kapcia (Tigase) commented 5 years ago

It seems the issue with weird presence is still happening and we are using build from October so it should already contain the fix. At any rate, I checked the logs and I don't see where it was generated - I adjusted logback as it was set to debug instead of trace for many packages.

Current logs got copied on kotali@ec2-54-188-212-175.us-west-2.compute.amazonaws.com to /home/tigase/tigase-server/unacked/ and most relevant entries are between 54 and 56. It seems that it may be somewhat related also to CSI as it was logged before and client also generated out_initial presence.

Wojciech Kapcia (Tigase) commented 5 years ago

(private)

Excerpts from logs:

[2020-10-18 20:06:18.334] [TRACE] [       in_2-sess-man] t.x.i.BindResource.preProcess() : Setting correct from attribute: alharith@tigase.im/Conversations.eLaN
[2020-10-18 20:06:18.334] [TRACE] [  socketReadThread-5] t.n.SocketThread.addAllWaiting(): waiting.size(): 1
[2020-10-18 20:06:18.334] [TRACE] [       in_2-sess-man] t.x.i.DomainFilter.preProcess() : Processing: from=c2s@ip-10-0-17-31.us-west-2.compute.internal/10.0.17.31_5223_188.49.36.104_58151, to=sess-man@ip-10-0-17-31.us-west-2.compute.internal, DATA=<inactive from="alharith@tigase.im/Conversations.eLaN" xmlns="urn:xmpp:csi:0"/>, SIZE=79, XMLNS=urn:xmpp:csi:0, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=null, STABLE_ID=5aa5afdd-40a1-49ae-81b4-0b73ba716e6a
[2020-10-18 20:06:18.334] [TRACE] [  socketReadThread-5] t.n.SocketThread.addAllWaiting(): ADDED OP_READ: TLS: SocketIO, ID: c2s@ip-10-0-17-31.us-west-2.compute.internal/10.0.17.31_5223_188.49.36.104_58151, connected Socket[addr=/188.49.36.104,port=58151,localport=5223]
[2020-10-18 20:06:18.334] [TRACE] [       in_2-sess-man] t.x.i.DomainFilter.getDomains() : Domains read from user session: ALL for VHost: tigase.im
[2020-10-18 20:06:18.334] [TRACE] [       in_2-sess-man] t.x.i.DomainFilter.preProcess() : DOMAINS setting is: ALL
[2020-10-18 20:06:18.334] [TRACE] [       in_2-sess-man] t.x.i.DomainFilter.filter()     : Filtering (packet): from=c2s@ip-10-0-17-31.us-west-2.compute.internal/10.0.17.31_5223_188.49.36.104_58151, to=sess-man@ip-10-0-17-31.us-west-2.compute.internal, DATA=<inactive from="alharith@tigase.im/Conversations.eLaN" xmlns="urn:xmpp:csi:0"/>, SIZE=79, XMLNS=urn:xmpp:csi:0, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=null, STABLE_ID=5aa5afdd-40a1-49ae-81b4-0b73ba716e6a
[2020-10-18 20:06:18.334] [TRACE] [urn:xmpp:csi:0-proc-0] t.x.i.DomainFilter.filter()    : Filtering (packet): from=c2s@ip-10-0-17-31.us-west-2.compute.internal/10.0.17.31_5223_188.49.36.104_58151, to=sess-man@ip-10-0-17-31.us-west-2.compute.internal, DATA=<inactive from="alharith@tigase.im/Conversations.eLaN" xmlns="urn:xmpp:csi:0"/>, SIZE=79, XMLNS=urn:xmpp:csi:0, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=null, STABLE_ID=5aa5afdd-40a1-49ae-81b4-0b73ba716e6a
[2020-10-18 20:06:18.334] [TRACE] [       in_2-sess-man] t.x.i.JabberIqPrivacy.allowed() : Using privacy list: null
[2020-10-18 20:06:18.335] [TRACE] [       in_2-sess-man] t.x.i.StartTLS.preProcess()     : VHost: (Wrapped)Domain: tigase.im, enabled: true, anonym: false, register: true, tls: true, maxusers: 0, s2sSecret: d5726b96-3fec-4197-a64b-fc1148bd0778, domainFilter: ALL, saslAllowedMechanisms: [PLAIN], trustedJids: [http@{clusterNode}]; Extensions: [HardenedModeVHostItemExtension(hardened-mode: secure), ServerInfoVHostItemExtension(abuse: [], admin: [], feedback: [], sales: [], security: [], support: []), ClientTrustVHostItemExtension(caCertPath: null, certRequired: false), BruteForceLockerVHostExtension(enabled: true,mode: IpJid, lockAfter: 3, disableAfter: 20, period: 60, lockTime: 60), MessageArchiveVHostItemExtension(enabled: true, defaultStore: unset, requiredStore: unset, retentionType: userDefined, saveMuc: Optional[user]), SeeOtherHostVHostItemExtension(enabled: true), PresenceSubscriptionVHostItemExtension(mode: global)]
[2020-10-18 20:06:18.335] [TRACE] [       in_2-sess-man] t.x.i.BindResource.preProcess() : Setting correct from attribute: alharith@tigase.im/Conversations.eLaN
[2020-10-18 20:06:18.335] [TRACE] [       in_2-sess-man] t.x.i.DomainFilter.preProcess() : Processing: from=c2s@ip-10-0-17-31.us-west-2.compute.internal/10.0.17.31_5223_188.49.36.104_58151, to=sess-man@ip-10-0-17-31.us-west-2.compute.internal, DATA=<presence xmlns="jabber:client" from="alharith@tigase.im/Conversations.eLaN"><c hash="sha-1" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" ver="PeKYibv9P9qF24DQsRGfza05Bn0="/></presence>, SIZE=211, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=1135d1c5-05b3-4f2b-92ea-ee82b793f744
[2020-10-18 20:06:18.335] [TRACE] [       in_2-sess-man] t.x.i.DomainFilter.getDomains() : Domains read from user session: ALL for VHost: tigase.im
[2020-10-18 20:06:18.335] [TRACE] [       in_2-sess-man] t.x.i.DomainFilter.preProcess() : DOMAINS setting is: ALL
[2020-10-18 20:06:18.335] [TRACE] [          pep-proc-0] t.x.i.JabberIqPrivacy.filter()  : Checking outbound packet: from=null, to=pubsub@ip-10-0-17-31.us-west-2.compute.internal, DATA=<presence to="alharith@tigase.im" xmlns="jabber:client" from="alharith@tigase.im/Conversations.eLaN"><c hash="sha-1" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" ver="PeKYibv9P9qF24DQsRGfza05Bn0="/></presence>, SIZE=235, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=null
[2020-10-18 20:06:18.335] [TRACE] [          pep-proc-0] t.x.i.JabberIqPrivacy.allowed() : Using privacy list: null
[2020-10-18 20:06:18.335] [TRACE] [          pep-proc-0] t.x.i.MobileV2.filter()         : no session for destination pubsub@ip-10-0-17-31.us-west-2.compute.internal for packet from=null, to=pubsub@ip-10-0-17-31.us-west-2.compute.internal, DATA=<presence to="alharith@tigase.im" xmlns="jabber:client" from="alharith@tigase.im/Conversations.eLaN"><c hash="sha-1" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" ver="PeKYibv9P9qF24DQsRGfza05Bn0="/></presence>, SIZE=235, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=null
[2020-10-18 20:06:18.335] [TRACE] [          pep-proc-0] t.x.i.DomainFilter.filter()     : Filtering (packet): from=c2s@ip-10-0-17-31.us-west-2.compute.internal/10.0.17.31_5223_188.49.36.104_58151, to=sess-man@ip-10-0-17-31.us-west-2.compute.internal, DATA=<presence xmlns="jabber:client" from="alharith@tigase.im/Conversations.eLaN"><c hash="sha-1" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" ver="PeKYibv9P9qF24DQsRGfza05Bn0="/></presence>, SIZE=211, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=1135d1c5-05b3-4f2b-92ea-ee82b793f744
[2020-10-18 20:06:18.335] [TRACE] [          pep-proc-0] t.x.i.DomainFilter.getDomains() : Domains read from user session: ALL for VHost: tigase.im
[2020-10-18 20:06:18.335] [TRACE] [presence-state-proc-0] t.x.i.PresenceState.process()  : alharith@tigase.im | out_initial presence found: from=c2s@ip-10-0-17-31.us-west-2.compute.internal/10.0.17.31_5223_188.49.36.104_58151, to=sess-man@ip-10-0-17-31.us-west-2.compute.internal, DATA=<presence xmlns="jabber:client" from="alharith@tigase.im/Conversations.eLaN"><c hash="sha-1" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" ver="PeKYibv9P9qF24DQsRGfza05Bn0="/></presence>, SIZE=211, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=1135d1c5-05b3-4f2b-92ea-ee82b793f744


[2020-10-18 20:06:18.336] [TRACE] [       in_2-sess-man] t.x.i.DomainFilter.filter()     : Filtering (packet): from=c2s@ip-10-0-17-31.us-west-2.compute.internal/10.0.17.31_5223_188.49.36.104_58151, to=sess-man@ip-10-0-17-31.us-west-2.compute.internal, DATA=<presence xmlns="jabber:client" from="alharith@tigase.im/Conversations.eLaN"><c hash="sha-1" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" ver="PeKYibv9P9qF24DQsRGfza05Bn0="/></presence>, SIZE=211, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=1135d1c5-05b3-4f2b-92ea-ee82b793f744


[2020-10-18 20:06:18.338] [TRACE] [     pool-1-thread-6] t.x.i.MessageCarbons.presenceUpdate(): session = XMPPSession=[hash=1464598109, username: alharith, resources: [XMPPResourceConnection=[user_jid=alharith@tigase.im/Conversations.eLaN, packets=33, connectioId=c2s@ip-10-0-17-31.us-west-2.compute.internal/10.0.17.31_5223_188.49.36.104_58151, domain=tigase.im, authState=AUTHORIZED, isAnon=false, isTmp=false, parentSession hash=1464598109, parentSession liveTime=26646]]]; processing presence = from=null, to=null, DATA=<presence xmlns="jabber:client" from="alharith@tigase.im/Conversations.eLaN"><c hash="sha-1" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" ver="PeKYibv9P9qF24DQsRGfza05Bn0="/></presence>, SIZE=211, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null



[2020-10-18 20:06:18.341] [TRACE] [          amp-proc-0] t.x.i.JabberIqPrivacy.filter()  : Checking outbound packet: from=null, to=null, DATA=<presence to="amp@ip-10-0-17-31.us-west-2.compute.internal" xmlns="jabber:client" from="alharith@tigase.im/Conversations.eLaN"><c hash="sha-1" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" ver="PeKYibv9P9qF24DQsRGfza05Bn0="/></presence>, SIZE=261, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=null
[2020-10-18 20:06:18.341] [TRACE] [          amp-proc-0] t.x.i.JabberIqPrivacy.allowed() : Using privacy list: null
[2020-10-18 20:06:18.341] [TRACE] [          amp-proc-0] t.x.i.MobileV2.filter()         : packet without destination
[2020-10-18 20:06:18.341] [TRACE] [          amp-proc-0] t.x.i.DomainFilter.filter()     : Filtering (packet): from=c2s@ip-10-0-17-31.us-west-2.compute.internal/10.0.17.31_5223_188.49.36.104_58151, to=sess-man@ip-10-0-17-31.us-west-2.compute.internal, DATA=<presence xmlns="jabber:client" from="alharith@tigase.im/Conversations.eLaN"><c hash="sha-1" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" ver="PeKYibv9P9qF24DQsRGfza05Bn0="/></presence>, SIZE=211, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=1135d1c5-05b3-4f2b-92ea-ee82b793f744
[2020-10-18 20:06:18.341] [TRACE] [          amp-proc-0] t.x.i.DomainFilter.getDomains() : Domains read from user session: ALL for VHost: tigase.im
[2020-10-18 20:06:18.341] [DEBUG] [    pool-31-thread-4] t.i.SocketIO.read()             : Read from channel 395 bytes [SocketIO, ID: null, connected Socket[addr=ip-10-0-32-65.us-west-2.compute.internal/10.0.32.65,port=5277,localport=42148]]
[2020-10-18 20:06:18.341] [TRACE] [presence-state-proc-0] t.x.i.JabberIqPrivacy.filter() : Checking outbound packet: from=null, to=c2s@ip-10-0-17-31.us-west-2.compute.internal/10.0.17.31_5223_188.49.36.104_58151, DATA=<presence to="alharith@tigase.im" xmlns="jabber:client" from="alharith@tigase.im/Conversations.eLaN"><c hash="sha-1" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" ver="PeKYibv9P9qF24DQsRGfza05Bn0="/></presence>, SIZE=235, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=null
[2020-10-18 20:06:18.341] [TRACE] [presence-state-proc-0] t.x.i.JabberIqPrivacy.allowed(): Using privacy list: null
[2020-10-18 20:06:18.341] [DEBUG] [    pool-31-thread-4] t.i.SocketIO.read()             : Read from channel 0 bytes [SocketIO, ID: null, connected Socket[addr=ip-10-0-32-65.us-west-2.compute.internal/10.0.32.65,port=5277,localport=42148]]
[2020-10-18 20:06:18.341] [TRACE] [presence-state-proc-0] t.x.i.MobileV2.filter()        : checking if packet should be queued from=null, to=c2s@ip-10-0-17-31.us-west-2.compute.internal/10.0.17.31_5223_188.49.36.104_58151, DATA=<presence to="alharith@tigase.im" xmlns="jabber:client" from="alharith@tigase.im/Conversations.eLaN"><c hash="sha-1" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" ver="PeKYibv9P9qF24DQsRGfza05Bn0="/></presence>, SIZE=235, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=null
[2020-10-18 20:06:18.341] [TRACE] [presence-state-proc-0] t.x.i.MobileV2.filter()        : queuing packet from=null, to=c2s@ip-10-0-17-31.us-west-2.compute.internal/10.0.17.31_5223_188.49.36.104_58151, DATA=<presence to="alharith@tigase.im" xmlns="jabber:client" from="alharith@tigase.im/Conversations.eLaN"><c hash="sha-1" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" ver="PeKYibv9P9qF24DQsRGfza05Bn0="/></presence>, SIZE=235, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=null
[2020-10-18 20:06:18.342] [DEBUG] [            in_2-c2s] t.i.TLSIO.write()               : TLS - Writing data, remaining: 211, loop_cnt: 0, TLSIO: TLS: SocketIO, ID: c2s@ip-10-0-17-31.us-west-2.compute.internal/10.0.17.31_5223_188.49.36.104_58151, connected Socket[addr=/188.49.36.104,port=58151,localport=5223], tlsWrapper: JcaTLSWrapper[WrapperStatus = OK, TLSEngineStatus = OK, HandshakeStatus = NOT_HANDSHAKING]
[2020-10-18 20:06:18.342] [TRACE] [ResultsListener-socketReadThread-6] t.n.SocketThread.run(): COMPLETED: SocketIO, ID: null, connected Socket[addr=ip-10-0-32-65.us-west-2.compute.internal/10.0.32.65,port=5277,localport=42148]
[2020-10-18 20:06:18.342] [DEBUG] [            in_2-c2s] t.i.SocketIO.write()            : SOCKET - Writing data, remaining: 240 [SocketIO, ID: c2s@ip-10-0-17-31.us-west-2.compute.internal/10.0.17.31_5223_188.49.36.104_58151, connected Socket[addr=/188.49.36.104,port=58151,localport=5223]]
[2020-10-18 20:06:18.342] [TRACE] [presence-state-proc-0] t.x.i.MobileV2.filter()        : queuing packet = from=null, to=c2s@ip-10-0-17-31.us-west-2.compute.internal/10.0.17.31_5223_188.49.36.104_58151, DATA=<presence to="alharith@tigase.im" xmlns="jabber:client" from="alharith@tigase.im/Conversations.eLaN"><c hash="sha-1" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" ver="PeKYibv9P9qF24DQsRGfza05Bn0="/></presence>, SIZE=235, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=null



[2020-10-18 20:06:45.853] [TRACE] [     pool-1-thread-1] t.x.i.MessageCarbons.presenceUpdate(): session = XMPPSession=[hash=1464598109, username: alharith, resources: [XMPPResourceConnection=[user_jid=alharith@tigase.im/Conversations.eLaN, packets=34, connectioId=c2s@ip-10-0-17-31.us-west-2.compute.internal/10.0.17.31_5223_188.49.36.104_58151, domain=tigase.im, authState=AUTHORIZED, isAnon=false, isTmp=false, parentSession hash=1464598109, parentSession liveTime=54161]]]; processing presence = from=null, to=null, DATA=<presence from="alharith@tigase.im/Conversations.eLaN" type="unavailable" xmlns="jabber:client"><c hash="sha-1" node="http://conversations.im" ver="PeKYibv9P9qF24DQsRGfza05Bn0=" xmlns="http://jabber.org/protocol/caps"/></presence>, SIZE=230, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=unavailable, STABLE_ID=null




[2020-10-18 20:07:31.882] [DEBUG] [ConnectionOpenThread] t.s.ConnectionManager.serviceStarted(): [[c2s]] Connection started: jid: null, C2SIOService, UniqueId: 10.0.17.31_5223_188.49.36.104_36688, type: <- incoming (accept), TLS: SocketIO, ID: null, connected Socket[addr=/188.49.36.104,port=36688,localport=5223]
[2020-10-18 20:07:31.882] [TRACE] [ConnectionOpenThread] t.n.SocketThread.addSocketServicePriv(): Adding to waiting: jid: null, C2SIOService, UniqueId: 10.0.17.31_5223_188.49.36.104_36688, type: <- incoming (accept), TLS: SocketIO, ID: c2s@ip-10-0-17-31.us-west-2.compute.internal/10.0.17.31_5223_188.49.36.104_36688, connected Socket[addr=/188.49.36.104,port=36688,localport=5223]
[2020-10-18 20:07:31.882] [TRACE] [  socketReadThread-2] t.n.SocketThread.run()          : Selector AWAKE: sun.nio.ch.EPollSelectorImpl@a6b379e
[2020-10-18 20:07:31.882] [TRACE] [  socketReadThread-2] t.n.SocketThread.addAllWaiting(): waiting.size(): 1



[2020-10-18 20:07:36.643] [DEBUG] [            in_2-c2s] t.s.x.StreamManagementIOProcessor.processCommand(): resuming stream with id = 9e7c6ad3-8755-4f4e-abc9-19e9bc66177b resending unacked packet = from=null, to=null, DATA=<presence from="alharith@tigase.im/Conversations.eLaN" xmlns="jabber:client"><c hash="sha-1" node="http://conversations.im" ver="PeKYibv9P9qF24DQsRGfza05Bn0=" xmlns="http://jabber.org/protocol/caps"/><delay stamp="2020-10-18T20:06:18.341Z" from="ip-10-0-17-31.us-west-2.compute.internal" xmlns="urn:xmpp:delay"/></presence>, SIZE=323, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null [jid: alharith@tigase.im/Conversations.eLaN, C2SIOService, UniqueId: 10.0.17.31_5223_188.49.36.104_58151, type: <- incoming (accept), TLS: SocketIO, ID: c2s@ip-10-0-17-31.us-west-2.compute.internal/10.0.17.31_5223_188.49.36.104_58151, disconnected Socket[addr=/188.49.36.104,port=58151,localport=5223]]



[2020-10-18 20:10:45.172] [WARN ] [            in_1-c2s] t.s.x.StreamManagementIOProcessor.getPacketWithStamp(): unacked packet without stanzaTo: null, and packetTo: null; setting from to: ip-10-0-17-31.us-west-2.compute.internal; packet: from=null, to=null, DATA=<presence from="alharith@tigase.im/Conversations.eLaN" xmlns="jabber:client"><c hash="sha-1" node="http://conversations.im" ver="PeKYibv9P9qF24DQsRGfza05Bn0=" xmlns="http://jabber.org/protocol/caps"/><delay stamp="2020-10-18T20:06:18.341Z" from="ip-10-0-17-31.us-west-2.compute.internal" xmlns="urn:xmpp:delay"/></presence>, SIZE=323, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null
[2020-10-18 20:10:45.183] [DEBUG] [            in_1-c2s] t.s.x.StreamManagementIOProcessor.processCommand(): resuming stream with id = 9e7c6ad3-8755-4f4e-abc9-19e9bc66177b resending unacked packet = from=null, to=null, DATA=<presence from="alharith@tigase.im/Conversations.eLaN" xmlns="jabber:client"><c hash="sha-1" node="http://conversations.im" ver="PeKYibv9P9qF24DQsRGfza05Bn0=" xmlns="http://jabber.org/protocol/caps"/><delay stamp="2020-10-18T20:06:18.341Z" from="ip-10-0-17-31.us-west-2.compute.internal" xmlns="urn:xmpp:delay"/><delay stamp="2020-10-18T20:07:36.643Z" from="ip-10-0-17-31.us-west-2.compute.internal" xmlns="urn:xmpp:delay"/></presence>, SIZE=435, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null [jid: alharith@tigase.im/Conversations.eLaN, C2SIOService, UniqueId: 10.0.17.31_5223_188.49.36.104_36688, type: <- incoming (accept), TLS: SocketIO, ID: c2s@ip-10-0-17-31.us-west-2.compute.internal/10.0.17.31_5223_188.49.36.104_36688, disconnected Socket[addr=/188.49.36.104,port=36688,localport=5223]]


[2020-10-18 20:10:45.184] [DEBUG] [            in_1-c2s] t.s.x.StreamManagementIOProcessor.processCommand(): resuming stream with id = 9e7c6ad3-8755-4f4e-abc9-19e9bc66177b resending unacked packet = from=null, to=null, DATA=<iq to="alharith@tigase.im/Conversations.eLaN" from="alharith@tigase.im" id="48C7067HE3aG" type="result" xmlns="jabber:client"><pubsub xmlns="http://jabber.org/protocol/pubsub"><items node="eu.siacs.conversations.axolotl.devicelist"><item id="current"><list xmlns="eu.siacs.conversations.axolotl"><device id="1436791148"/></list></item></items><set xmlns="http://jabber.org/protocol/rsm"><first index="0">CData size: 12</first><last>CData size: 12</last><count>1</count></set></pubsub></iq>, SIZE=486, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=result, STABLE_ID=null [jid: alharith@tigase.im/Conversations.eLaN, C2SIOService, UniqueId: 10.0.17.31_5223_188.49.36.104_36688, type: <- incoming (accept), TLS: SocketIO, ID: c2s@ip-10-0-17-31.us-west-2.compute.internal/10.0.17.31_5223_188.49.36.104_36688, disconnected Socket[addr=/188.49.36.104,port=36688,localport=5223]]
[2020-10-18 20:10:45.184] [DEBUG] [            in_1-c2s] t.s.x.StreamManagementIOProcessor.processCommand(): resuming stream with id = 9e7c6ad3-8755-4f4e-abc9-19e9bc66177b resending unacked packet = from=null, to=null, DATA=<iq to="alharith@tigase.im/Conversations.eLaN" from="alharith@tigase.im" id="DtMVUstZMoa4" type="result" xmlns="jabber:client"><pubsub xmlns="http://jabber.org/protocol/pubsub"><items node="eu.siacs.conversations.axolotl.devicelist"><item id="current"><list xmlns="eu.siacs.conversations.axolotl"><device id="1436791148"/></list></item></items><set xmlns="http://jabber.org/protocol/rsm"><first index="0">CData size: 12</first><last>CData size: 12</last><count>1</count></set></pubsub></iq>, SIZE=486, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=result, STABLE_ID=null [jid: alharith@tigase.im/Conversations.eLaN, C2SIOService, UniqueId: 10.0.17.31_5223_188.49.36.104_36688, type: <- incoming (accept), TLS: SocketIO, ID: c2s@ip-10-0-17-31.us-west-2.compute.internal/10.0.17.31_5223_188.49.36.104_36688, disconnected Socket[addr=/188.49.36.104,port=36688,localport=5223]]

Andrzej Wójcik (Tigase) commented 5 years ago

I've reviewed code and logs and it looks like sess-man actually resends received messages on its own (same thread is used for filtering outgoing packets as it was for calling preprocess() filters).

But still, I was not able to find cause of this issue.
Wojciech Kapcia (Tigase) commented 5 years ago

As I said before - the log level was not detailed enough so I did not dedicate more time to investigate it. Let's wait for the next occurrence and with more data we should be able to track it.
Wojciech Kapcia (Tigase) commented 4 years ago

Quite possibly same cause as in #issue #1271 - faulty stamping of from attribute in incoming stanzas.

Wojciech Kapcia (Tigase) commented 4 years ago

Today we had another notification:

[2021-09-05 15:39:46:069] [WARNING ] [scheduler_pool-7-thread-1-c2s ] StreamManagementIOProcessor$OutQueue$Entry.getPacketWithStamp(): unacked packet without stanzaTo: null, and packetTo: null; setting from to: ip-172-31-20-109.us-west-2.compute.internal; packet: from=null, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/><delay from="ip-172-31-20-109.us-west-2.compute.internal" xmlns="urn:xmpp:delay" stamp="2021-09-05T15:26:10.842Z"/></presence>, SIZE=384, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null

I managed to get the logs:

[2021-09-05 15:29:37.115] [DEBUG] [    pool-35-thread-1] t.s.x.StreamManagementIOProcessor.resumeStream(): Resuming stream with id = 758ce683-de8d-4d68-8ffa-4cf2c9764127 with 15 packets waiting for ack, local h = 32 and remote h = 132 [jid: izan@sure.im, C2SIOService, UniqueId: 172.22.0.2_5223_172.31.10.118_35718, type: <- incoming (accept), TLS: SocketIO, ID: c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.10.118_35718, connected Socket[addr=/172.31.10.118,port=35718,localport=5223]]
…
[2021-09-05 15:29:37.121] [TRACE] [            in_2-c2s] t.s.x.StreamManagementIOProcessor.processCommand(): resuming stream with id = 758ce683-de8d-4d68-8ffa-4cf2c9764127 resending unacked packet = from=null, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/><delay from="ip-172-31-20-109.us-west-2.compute.internal" xmlns="urn:xmpp:delay" stamp="2021-09-05T15:26:10.842Z"/></presence>, SIZE=384, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null [jid: izan@sure.im/Conversations.yDBW, C2SIOService, UniqueId: 172.22.0.2_5223_172.31.31.162_61132, type: <- incoming (accept), TLS: SocketIO, ID: c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.31.162_61132, connected Socket[addr=/172.31.31.162,port=61132,localport=5223]]
[2021-09-05 15:29:37.121] [TRACE] [            in_2-c2s] t.s.x.StreamManagementIOProcessor.processOutgoing(): Queuing StreamManagement packet: from=null, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/><delay from="ip-172-31-20-109.us-west-2.compute.internal" xmlns="urn:xmpp:delay" stamp="2021-09-05T15:26:10.842Z"/></presence>, SIZE=384, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null, queue size: 19 [jid: izan@sure.im/Conversations.yDBW, C2SIOService, UniqueId: 172.22.0.2_5223_172.31.10.118_35718, type: <- incoming (accept), TLS: SocketIO, ID: c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.10.118_35718, connected Socket[addr=/172.31.10.118,port=35718,localport=5223]]
…
[2021-09-05 15:39:46.070] [WARN ] [scheduler_pool-7-thread-1-c2s] t.s.x.StreamManagementIOProcessor.getPacketWithStamp(): unacked packet without stanzaTo: null, and packetTo: null; setting from to: ip-172-31-20-109.us-west-2.compute.internal; packet: from=null, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/><delay from="ip-172-31-20-109.us-west-2.compute.internal" xmlns="urn:xmpp:delay" stamp="2021-09-05T15:26:10.842Z"/></presence>, SIZE=384, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null

So it seems that initially when the packet arrives in StreamManagementIOProcessor we know to which session it belongs (and to which user) and later on it's gone / not passed when packet (Entry) is due to re-delivery? Should we maybe try to set stanza's to attribute (if missing) in .processOutgoing() to the JID associated with the service? What do you think @andrzej.wojcik ?

Nevertheless, it's still curious why such packet ended up in StreamManagementIOProcessor in the first place (with from but without to). I dug more into the logs:

tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.774] [TRACE] [    pool-35-thread-9] t.s.x.ClientConnectionManager.processSocketData(): Processing socket data: from=null, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=208, XMLNS=null, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null from connection: c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.31.162_61132
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.775] [TRACE] [    pool-35-thread-9] t.s.x.ClientConnectionManager.processSocketData(): XMLNS set for packet: from=null, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence xmlns="jabber:client"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=230, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null from connection: c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.31.162_61132
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.781] [TRACE] [ in_2-message-router] t.s.MessageRouter.processPacket(): Processing packet: from=c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.31.162_61132, to=sess-man@ip-172-31-20-109.us-west-2.compute.internal, serverAuthorisedStanzaFrom=Optional[izan@sure.im/Conversations.yDBW], DATA=<presence xmlns="jabber:client"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=230, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.782] [TRACE] [ in_2-message-router] t.s.MessageRouter.processPacket(): 1. Packet will be processed by: sess-man@ip-172-31-20-109.us-west-2.compute.internal, from=c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.31.162_61132, to=sess-man@ip-172-31-20-109.us-west-2.compute.internal, serverAuthorisedStanzaFrom=Optional[izan@sure.im/Conversations.yDBW], DATA=<presence xmlns="jabber:client"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=230, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.784] [TRACE] [      in_26-sess-man] t.c.SessionManagerClustered.processPacket(): Received packet: from=c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.31.162_61132, to=sess-man@ip-172-31-20-109.us-west-2.compute.internal, serverAuthorisedStanzaFrom=Optional[izan@sure.im/Conversations.yDBW], DATA=<presence xmlns="jabber:client"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=230, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.784] [TRACE] [      in_26-sess-man] t.s.c.s.OnlineUsersCachingStrategy.getNodesForPacketForward(): Packet not suitable for forwarding: from=c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.31.162_61132, to=sess-man@ip-172-31-20-109.us-west-2.compute.internal, serverAuthorisedStanzaFrom=Optional[izan@sure.im/Conversations.yDBW], DATA=<presence xmlns="jabber:client"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=230, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=1130d3fb-0b34-40a2-899a-c1ca199e1371
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.784] [TRACE] [      in_26-sess-man] t.c.s.DefaultClusteringStrategyAbstract.processPacket(): No cluster nodes found for packet forward: from=c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.31.162_61132, to=sess-man@ip-172-31-20-109.us-west-2.compute.internal, serverAuthorisedStanzaFrom=Optional[izan@sure.im/Conversations.yDBW], DATA=<presence xmlns="jabber:client"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=230, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=1130d3fb-0b34-40a2-899a-c1ca199e1371
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.784] [TRACE] [      in_26-sess-man] t.s.x.SessionManager.processPacket(): processing packet: from=c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.31.162_61132, to=sess-man@ip-172-31-20-109.us-west-2.compute.internal, serverAuthorisedStanzaFrom=Optional[izan@sure.im/Conversations.yDBW], DATA=<presence xmlns="jabber:client"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=230, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=1130d3fb-0b34-40a2-899a-c1ca199e1371, connection: XMPPResourceConnection=[user_jid=izan@sure.im/Conversations.yDBW, packets=36, connectioId=c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.31.162_61132, domain=sure.im, authState=AUTHORIZED, isAnon=false, isTmp=false, parentSession hash=1493693687, parentSession liveTime=5101]
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.785] [TRACE] [      in_26-sess-man] t.x.i.DomainFilter.preProcess() : Processing: from=c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.31.162_61132, to=sess-man@ip-172-31-20-109.us-west-2.compute.internal, serverAuthorisedStanzaFrom=Optional[izan@sure.im/Conversations.yDBW], DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=269, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=1130d3fb-0b34-40a2-899a-c1ca199e1371
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.785] [TRACE] [      in_26-sess-man] t.s.x.SessionManager.walk()     : XMPPProcessorIfc: MessageAmp (amp)Request: from=c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.31.162_61132, to=sess-man@ip-172-31-20-109.us-west-2.compute.internal, serverAuthorisedStanzaFrom=Optional[izan@sure.im/Conversations.yDBW], DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=269, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=1130d3fb-0b34-40a2-899a-c1ca199e1371, conn: XMPPResourceConnection=[user_jid=izan@sure.im/Conversations.yDBW, packets=37, connectioId=c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.31.162_61132, domain=sure.im, authState=AUTHORIZED, isAnon=false, isTmp=false, parentSession hash=1493693687, parentSession liveTime=5102]
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.786] [TRACE] [      in_26-sess-man] t.s.x.SessionManager.walk()     : XMPPProcessorIfc: PepPlugin (pep)Request: from=c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.31.162_61132, to=sess-man@ip-172-31-20-109.us-west-2.compute.internal, serverAuthorisedStanzaFrom=Optional[izan@sure.im/Conversations.yDBW], DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=269, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=1130d3fb-0b34-40a2-899a-c1ca199e1371, conn: XMPPResourceConnection=[user_jid=izan@sure.im/Conversations.yDBW, packets=37, connectioId=c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.31.162_61132, domain=sure.im, authState=AUTHORIZED, isAnon=false, isTmp=false, parentSession hash=1493693687, parentSession liveTime=5103]
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.786] [TRACE] [      in_26-sess-man] t.s.x.SessionManager.walk()     : XMPPProcessorIfc: PresenceState (presence-state)Request: from=c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.31.162_61132, to=sess-man@ip-172-31-20-109.us-west-2.compute.internal, serverAuthorisedStanzaFrom=Optional[izan@sure.im/Conversations.yDBW], DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=269, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=1130d3fb-0b34-40a2-899a-c1ca199e1371, conn: XMPPResourceConnection=[user_jid=izan@sure.im/Conversations.yDBW, packets=37, connectioId=c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.31.162_61132, domain=sure.im, authState=AUTHORIZED, isAnon=false, isTmp=false, parentSession hash=1493693687, parentSession liveTime=5103]
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.787] [TRACE] [presence-state-proc-1] t.x.i.PresenceState.process()  : izan@sure.im | out_initial presence found: from=c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.31.162_61132, to=sess-man@ip-172-31-20-109.us-west-2.compute.internal, serverAuthorisedStanzaFrom=Optional[izan@sure.im/Conversations.yDBW], DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=269, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=1130d3fb-0b34-40a2-899a-c1ca199e1371
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.788] [TRACE] [          pep-proc-1] t.x.i.JabberIqPrivacy.filter()  : Checking outbound packet: from=null, to=pubsub@ip-172-31-20-109.us-west-2.compute.internal, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client" to="izan@sure.im"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=287, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.788] [TRACE] [          pep-proc-1] t.x.i.MobileV2.filter()         : no session for destination pubsub@ip-172-31-20-109.us-west-2.compute.internal for packet from=null, to=pubsub@ip-172-31-20-109.us-west-2.compute.internal, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client" to="izan@sure.im"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=287, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.788] [TRACE] [          pep-proc-1] t.x.i.DomainFilter.filter()     : Filtering (packet): from=c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.31.162_61132, to=sess-man@ip-172-31-20-109.us-west-2.compute.internal, serverAuthorisedStanzaFrom=Optional[izan@sure.im/Conversations.yDBW], DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=269, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=1130d3fb-0b34-40a2-899a-c1ca199e1371
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.789] [TRACE] [ in_5-message-router] t.s.MessageRouter.processPacket(): Processing packet: from=sess-man@ip-172-31-20-109.us-west-2.compute.internal, to=pubsub@ip-172-31-20-109.us-west-2.compute.internal, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client" to="izan@sure.im"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=287, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.789] [TRACE] [      in_26-sess-man] t.s.c.s.OnlineUsersCachingStrategy.getNodesForPacketForward(): Selected nodes: [sess-man@ip-172-31-38-91.us-west-2.compute.internal], for packet: from=null, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=269, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.790] [TRACE] [     pool-1-thread-5] t.x.i.MessageCarbons.presenceUpdate(): session = XMPPSession=[hash=1493693687, username: izan, resources: [XMPPResourceConnection=[user_jid=izan@sure.im/Conversations.yDBW, packets=37, connectioId=c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.31.162_61132, domain=sure.im, authState=AUTHORIZED, isAnon=false, isTmp=false, parentSession hash=1493693687, parentSession liveTime=5107]]]; processing presence = from=null, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=269, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.791] [TRACE] [ in_5-message-router] t.s.MessageRouter.processPacket(): 1. Packet will be processed by: pubsub@ip-172-31-20-109.us-west-2.compute.internal, from=sess-man@ip-172-31-20-109.us-west-2.compute.internal, to=pubsub@ip-172-31-20-109.us-west-2.compute.internal, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client" to="izan@sure.im"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=287, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.791] [TRACE] [      in_26-sess-man] t.c.ClusterConnectionManager.executeCommand(): Called fromNode: null, visitedNodes: null, data: null, packets: [<cluster type="set" to="sess-man@ip-172-31-38-91.us-west-2.compute.internal" pr="CLUSTER" id="cl-402686" from="sess-man@ip-172-31-20-109.us-west-2.compute.internal" xmlns="tigase:cluster"><control><visited-nodes><node-id>sess-man@ip-172-31-20-109.us-west-2.compute.internal</node-id></visited-nodes><method-call name="sess-man-user-presence-sm-cmd"><par name="userId">izan@sure.im</par><par name="resource">Conversations.yDBW</par><par name="connId">c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.31.162_61132</par><par name="xmppSessId">3a8bcb51-db4e-453d-a7ee-7b22b68c080d</par><par name="auth-time">413</par><par name="creation-t">1630855565270</par><par name="login_t">413</par><par name="pres-type">initial</par></method-call><first-node>sess-man@ip-172-31-20-109.us-west-2.compute.internal</first-node></control><data><presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence></data></cluster>]
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.791] [TRACE] [      in_26-sess-man] t.c.ClusterElement.<init>()     : Parsing cluster element: <cluster type="set" to="sess-man@ip-172-31-38-91.us-west-2.compute.internal" pr="CLUSTER" id="cl-402686" from="sess-man@ip-172-31-20-109.us-west-2.compute.internal" xmlns="tigase:cluster"><control><visited-nodes><node-id>sess-man@ip-172-31-20-109.us-west-2.compute.internal</node-id></visited-nodes><method-call name="sess-man-user-presence-sm-cmd"><par name="userId">izan@sure.im</par><par name="resource">Conversations.yDBW</par><par name="connId">c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.31.162_61132</par><par name="xmppSessId">3a8bcb51-db4e-453d-a7ee-7b22b68c080d</par><par name="auth-time">413</par><par name="creation-t">1630855565270</par><par name="login_t">413</par><par name="pres-type">initial</par></method-call><first-node>sess-man@ip-172-31-20-109.us-west-2.compute.internal</first-node></control><data><presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence></data></cluster>
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.792] [TRACE] [          amp-proc-1] t.x.i.JabberIqPrivacy.filter()  : Checking outbound packet: from=null, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client" to="amp@ip-172-31-20-109.us-west-2.compute.internal"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=322, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.792] [TRACE] [      in_26-sess-man] t.x.i.DomainFilter.filter()     : Filtering (packet): from=c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.31.162_61132, to=sess-man@ip-172-31-20-109.us-west-2.compute.internal, serverAuthorisedStanzaFrom=Optional[izan@sure.im/Conversations.yDBW], DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=269, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=1130d3fb-0b34-40a2-899a-c1ca199e1371
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.793] [TRACE] [presence-state-proc-1] t.x.i.PresenceAbstract.sendPresence(): Sending presence info: from=null, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client" to="piza@yax.im"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=286, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.794] [TRACE] [presence-state-proc-1] t.x.i.PresenceAbstract.sendPresence(): Sending presence info: from=null, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client" to="babacb@yax.im"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=288, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.794] [TRACE] [presence-state-proc-1] t.x.i.JabberIqPrivacy.filter() : Checking outbound packet: from=null, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client" to="piza@yax.im"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=286, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.794] [TRACE] [presence-state-proc-1] t.x.i.JabberIqPrivacy.filter() : Checking outbound packet: from=null, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client" to="babacb@yax.im"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=288, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.794] [TRACE] [presence-state-proc-1] t.x.i.JabberIqPrivacy.filter() : Checking outbound packet: from=null, to=c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.31.162_61132, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client" to="izan@sure.im"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=287, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.795] [TRACE] [presence-state-proc-1] t.x.i.MobileV2.filter()        : checking if packet should be queued from=null, to=c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.31.162_61132, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client" to="izan@sure.im"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=287, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.795] [TRACE] [presence-state-proc-1] t.x.i.MobileV2.filter()        : queuing packet from=null, to=c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.31.162_61132, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client" to="izan@sure.im"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=287, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.795] [TRACE] [presence-state-proc-1] t.x.i.MobileV2.filter()        : queuing packet = from=null, to=c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.31.162_61132, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client" to="izan@sure.im"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=287, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.795] [TRACE] [presence-state-proc-1] t.x.i.DomainFilter.filter()    : Filtering (packet): from=c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.31.162_61132, to=sess-man@ip-172-31-20-109.us-west-2.compute.internal, serverAuthorisedStanzaFrom=Optional[izan@sure.im/Conversations.yDBW], DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=269, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=1130d3fb-0b34-40a2-899a-c1ca199e1371
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.795] [TRACE] [ in_3-message-router] t.s.MessageRouter.processPacket(): Processing packet: from=sess-man@ip-172-31-20-109.us-west-2.compute.internal, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client" to="babacb@yax.im"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=288, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.797] [TRACE] [        in_5-cl-comp] t.c.ClusterElement.<init>()     : Parsing cluster element: <cluster type="set" to="sess-man@ip-172-31-38-91.us-west-2.compute.internal" pr="CLUSTER" id="cl-402686" from="sess-man@ip-172-31-20-109.us-west-2.compute.internal" xmlns="tigase:cluster"><control><visited-nodes><node-id>sess-man@ip-172-31-20-109.us-west-2.compute.internal</node-id></visited-nodes><method-call name="sess-man-user-presence-sm-cmd"><par name="userId">izan@sure.im</par><par name="resource">Conversations.yDBW</par><par name="connId">c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.31.162_61132</par><par name="xmppSessId">3a8bcb51-db4e-453d-a7ee-7b22b68c080d</par><par name="auth-time">413</par><par name="creation-t">1630855565270</par><par name="login_t">413</par><par name="pres-type">initial</par></method-call><first-node>sess-man@ip-172-31-20-109.us-west-2.compute.internal</first-node></control><data><presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence></data></cluster>
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.797] [TRACE] [          amp-proc-1] t.x.i.DomainFilter.filter()     : Filtering (packet): from=c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.31.162_61132, to=sess-man@ip-172-31-20-109.us-west-2.compute.internal, serverAuthorisedStanzaFrom=Optional[izan@sure.im/Conversations.yDBW], DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=269, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=1130d3fb-0b34-40a2-899a-c1ca199e1371
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.813] [TRACE] [ in_3-message-router] t.s.MessageRouter.processPacket(): 2. Packet will be processed by: s2s@ip-172-31-20-109.us-west-2.compute.internal, from=sess-man@ip-172-31-20-109.us-west-2.compute.internal, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client" to="babacb@yax.im"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=288, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.814] [TRACE] [            in_6-s2s] t.s.x.S2SConnectionManager.processPacket(): Processing packet: from=sess-man@ip-172-31-20-109.us-west-2.compute.internal, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client" to="babacb@yax.im"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=288, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.814] [TRACE] [            in_6-s2s] t.s.x.CIDConnections.sendPacket(): Sending packet: from=null, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence from="izan@sure.im/Conversations.yDBW" to="babacb@yax.im"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=266, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.814] [TRACE] [            in_6-s2s] t.s.ConnectionManager.writePacketToSocket(): Writing packet: from=null, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence from="izan@sure.im/Conversations.yDBW" to="babacb@yax.im"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=266, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null [CID: sure.im@yax.im, IN: 1, OUT: 1, authenticated: true, remote-session-id: 521ed3cc-f39d-4b1d-a893-63a16a7b6352, jid: sure.im@yax.im, S2SIOService, UniqueId: 172.22.0.2_51868_212.21.75.16_5269, type: -> outgoing (connect), TLS: SocketIO, ID: sure.im@yax.im/b692c59a-ebb1-49f9-bb8b-e57e9067e64a, connected Socket[addr=/212.21.75.16,port=5269,localport=51868]]
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.814] [TRACE] [            in_6-s2s] t.s.x.CIDConnections.sendPacket(): Packet: from=null, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence from="izan@sure.im/Conversations.yDBW" to="babacb@yax.im"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=266, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null sent over connection: CID: sure.im@yax.im, IN: 1, OUT: 1, authenticated: true, remote-session-id: 521ed3cc-f39d-4b1d-a893-63a16a7b6352, jid: sure.im@yax.im, S2SIOService, UniqueId: 172.22.0.2_51868_212.21.75.16_5269, type: -> outgoing (connect), TLS: SocketIO, ID: sure.im@yax.im/b692c59a-ebb1-49f9-bb8b-e57e9067e64a, connected Socket[addr=/212.21.75.16,port=5269,localport=51868]
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.817] [TRACE] [ in_2-message-router] t.s.MessageRouter.processPacket(): Processing packet: from=sess-man@ip-172-31-20-109.us-west-2.compute.internal, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client" to="piza@yax.im"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=286, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.819] [TRACE] [ in_2-message-router] t.s.MessageRouter.processPacket(): 2. Packet will be processed by: s2s@ip-172-31-20-109.us-west-2.compute.internal, from=sess-man@ip-172-31-20-109.us-west-2.compute.internal, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client" to="piza@yax.im"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=286, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.819] [TRACE] [ in_2-message-router] t.s.MessageRouter.processPacket(): Processing packet: from=sess-man@ip-172-31-20-109.us-west-2.compute.internal, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client" to="amp@ip-172-31-20-109.us-west-2.compute.internal"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=322, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.819] [TRACE] [            in_6-s2s] t.s.x.S2SConnectionManager.processPacket(): Processing packet: from=sess-man@ip-172-31-20-109.us-west-2.compute.internal, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client" to="piza@yax.im"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=286, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.819] [TRACE] [            in_6-s2s] t.s.x.CIDConnections.sendPacket(): Sending packet: from=null, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence from="izan@sure.im/Conversations.yDBW" to="piza@yax.im"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=264, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.819] [TRACE] [ in_2-message-router] t.s.MessageRouter.processPacket(): 1. Packet will be processed by: amp@ip-172-31-20-109.us-west-2.compute.internal, from=sess-man@ip-172-31-20-109.us-west-2.compute.internal, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client" to="amp@ip-172-31-20-109.us-west-2.compute.internal"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=322, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.819] [TRACE] [            in_2-amp] t.s.a.AmpComponent.processPacket(): My packet: from=sess-man@ip-172-31-20-109.us-west-2.compute.internal, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client" to="amp@ip-172-31-20-109.us-west-2.compute.internal"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=322, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.819] [TRACE] [            in_2-amp] t.s.a.a.Broadcast.preprocess()  : processing packet = from=sess-man@ip-172-31-20-109.us-west-2.compute.internal, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client" to="amp@ip-172-31-20-109.us-west-2.compute.internal"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=322, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.819] [TRACE] [            in_6-s2s] t.s.ConnectionManager.writePacketToSocket(): Writing packet: from=null, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence from="izan@sure.im/Conversations.yDBW" to="piza@yax.im"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=264, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null [CID: sure.im@yax.im, IN: 1, OUT: 1, authenticated: true, remote-session-id: 521ed3cc-f39d-4b1d-a893-63a16a7b6352, jid: sure.im@yax.im, S2SIOService, UniqueId: 172.22.0.2_51868_212.21.75.16_5269, type: -> outgoing (connect), TLS: SocketIO, ID: sure.im@yax.im/b692c59a-ebb1-49f9-bb8b-e57e9067e64a, connected Socket[addr=/212.21.75.16,port=5269,localport=51868]]
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.820] [TRACE] [            in_6-s2s] t.s.x.CIDConnections.sendPacket(): Packet: from=null, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence from="izan@sure.im/Conversations.yDBW" to="piza@yax.im"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=264, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null sent over connection: CID: sure.im@yax.im, IN: 1, OUT: 1, authenticated: true, remote-session-id: 521ed3cc-f39d-4b1d-a893-63a16a7b6352, jid: sure.im@yax.im, S2SIOService, UniqueId: 172.22.0.2_51868_212.21.75.16_5269, type: -> outgoing (connect), TLS: SocketIO, ID: sure.im@yax.im/b692c59a-ebb1-49f9-bb8b-e57e9067e64a, connected Socket[addr=/212.21.75.16,port=5269,localport=51868]
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.841] [TRACE] [    pool-35-thread-2] t.c.ClusterConnectionManager.processSocketData(): Processing socket data: from=null, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<route pr="PRESENCE" to="c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.31.162_61132" perm="NONE" from="sess-man@ip-172-31-38-91.us-west-2.compute.internal"><presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence></route>, SIZE=458, XMLNS=null, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.841] [DEBUG] [      out_10-cl-comp] t.c.ClusterConnectionManager.processOutPacket(): Unexpected packet on cluster connection: from=sess-man@ip-172-31-38-91.us-west-2.compute.internal, to=c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.31.162_61132, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=269, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.842] [TRACE] [ in_2-message-router] t.s.MessageRouter.processPacket(): Processing packet: from=sess-man@ip-172-31-38-91.us-west-2.compute.internal, to=c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.31.162_61132, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=269, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.842] [TRACE] [ in_2-message-router] t.s.MessageRouter.processPacket(): 1. Packet will be processed by: c2s@ip-172-31-20-109.us-west-2.compute.internal, from=sess-man@ip-172-31-38-91.us-west-2.compute.internal, to=c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.31.162_61132, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=269, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.842] [TRACE] [            in_2-c2s] t.s.x.ClientConnectionManager.processPacket(): Processing packet: from=sess-man@ip-172-31-38-91.us-west-2.compute.internal, to=c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.31.162_61132, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=269, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.842] [TRACE] [            in_2-c2s] t.s.ConnectionManager.writePacketToSocket(): Writing packet: from=sess-man@ip-172-31-38-91.us-west-2.compute.internal, to=c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.31.162_61132, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=269, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null [jid: izan@sure.im/Conversations.yDBW, C2SIOService, UniqueId: 172.22.0.2_5223_172.31.31.162_61132, type: <- incoming (accept), TLS: SocketIO, ID: c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.31.162_61132, connected Socket[addr=/172.31.31.162,port=61132,localport=5223]]
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:10.842] [TRACE] [            in_2-c2s] t.s.x.StreamManagementIOProcessor.processOutgoing(): Queuing StreamManagement packet: from=sess-man@ip-172-31-38-91.us-west-2.compute.internal, to=c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.31.162_61132, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=269, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null, queue size: 4 [jid: izan@sure.im/Conversations.yDBW, C2SIOService, UniqueId: 172.22.0.2_5223_172.31.31.162_61132, type: <- incoming (accept), TLS: SocketIO, ID: c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.31.162_61132, connected Socket[addr=/172.31.31.162,port=61132,localport=5223]]
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:11.158] [TRACE] [    pool-35-thread-1] t.s.x.S2SConnectionManager.processSocketData(): Processing socket data: from=null, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence to="izan@sure.im" from="piza@yax.im/Conversations.O-pp" xml:lang="en"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" xmlns="http://jabber.org/protocol/caps" node="http://conversations.im" hash="sha-1"/><idle xmlns="urn:xmpp:idle:1" since="2021-09-05T13:32:07.895Z"/><delay from="yax.im" xmlns="urn:xmpp:delay" stamp="2021-09-05T13:32:09Z"/></presence>, SIZE=352, XMLNS=null, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null [CID: sure.im@yax.im, IN: 1, OUT: 1, authenticated: true, remote-session-id: a2716322-c2a8-4ebd-8507-6cdb8418a797, jid: null, S2SIOService, UniqueId: 172.22.0.2_5269_172.31.10.118_52600, type: <- incoming (accept), TLS: SocketIO, ID: sure.im@yax.im/33b36cba-dc80-42fc-872e-00f45e5c0643, connected Socket[addr=/172.31.10.118,port=52600,localport=5269]]
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:11.158] [DEBUG] [    pool-35-thread-1] t.s.x.p.AuthenticatorSelectorManager.isAllowed(): Connection already authenticated, skipping processor: tigase.server.xmppserver.proc.SaslExternal@1c71d704, methodsAvailable: [tigase.server.xmppserver.proc.SaslExternal@1c71d704, tigase.server.xmppserver.proc.Dialback@d5d9d92], checking packet: from=null, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence to="izan@sure.im" from="piza@yax.im/Conversations.O-pp" xmlns="jabber:server" xml:lang="en"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" xmlns="http://jabber.org/protocol/caps" node="http://conversations.im" hash="sha-1"/><idle xmlns="urn:xmpp:idle:1" since="2021-09-05T13:32:07.895Z"/><delay from="yax.im" xmlns="urn:xmpp:delay" stamp="2021-09-05T13:32:09Z"/></presence>, SIZE=374, XMLNS=jabber:server, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null [CID: sure.im@yax.im, IN: 1, OUT: 1, authenticated: true, remote-session-id: a2716322-c2a8-4ebd-8507-6cdb8418a797, jid: null, S2SIOService, UniqueId: 172.22.0.2_5269_172.31.10.118_52600, type: <- incoming (accept), TLS: SocketIO, ID: sure.im@yax.im/33b36cba-dc80-42fc-872e-00f45e5c0643, connected Socket[addr=/172.31.10.118,port=52600,localport=5269]]
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:11.158] [DEBUG] [    pool-35-thread-1] t.s.x.p.AuthenticatorSelectorManager.isAllowed(): Connection already authenticated, skipping processor: tigase.server.xmppserver.proc.Dialback@d5d9d92, methodsAvailable: [tigase.server.xmppserver.proc.SaslExternal@1c71d704, tigase.server.xmppserver.proc.Dialback@d5d9d92], checking packet: from=null, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence to="izan@sure.im" from="piza@yax.im/Conversations.O-pp" xmlns="jabber:server" xml:lang="en"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" xmlns="http://jabber.org/protocol/caps" node="http://conversations.im" hash="sha-1"/><idle xmlns="urn:xmpp:idle:1" since="2021-09-05T13:32:07.895Z"/><delay from="yax.im" xmlns="urn:xmpp:delay" stamp="2021-09-05T13:32:09Z"/></presence>, SIZE=374, XMLNS=jabber:server, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null [CID: sure.im@yax.im, IN: 1, OUT: 1, authenticated: true, remote-session-id: a2716322-c2a8-4ebd-8507-6cdb8418a797, jid: null, S2SIOService, UniqueId: 172.22.0.2_5269_172.31.10.118_52600, type: <- incoming (accept), TLS: SocketIO, ID: sure.im@yax.im/33b36cba-dc80-42fc-872e-00f45e5c0643, connected Socket[addr=/172.31.10.118,port=52600,localport=5269]]
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:11.158] [TRACE] [    pool-35-thread-1] t.s.x.S2SConnectionManager.processSocketData(): Adding packet out: from=null, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence to="izan@sure.im" from="piza@yax.im/Conversations.O-pp" xmlns="jabber:client" xml:lang="en"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" xmlns="http://jabber.org/protocol/caps" node="http://conversations.im" hash="sha-1"/><idle xmlns="urn:xmpp:idle:1" since="2021-09-05T13:32:07.895Z"/><delay from="yax.im" xmlns="urn:xmpp:delay" stamp="2021-09-05T13:32:09Z"/></presence>, SIZE=374, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null [CID: sure.im@yax.im, IN: 1, OUT: 1, authenticated: true, remote-session-id: a2716322-c2a8-4ebd-8507-6cdb8418a797, jid: null, S2SIOService, UniqueId: 172.22.0.2_5269_172.31.10.118_52600, type: <- incoming (accept), TLS: SocketIO, ID: sure.im@yax.im/33b36cba-dc80-42fc-872e-00f45e5c0643, connected Socket[addr=/172.31.10.118,port=52600,localport=5269]]
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:11.158] [TRACE] [ in_3-message-router] t.s.MessageRouter.processPacket(): Processing packet: from=s2s@ip-172-31-20-109.us-west-2.compute.internal, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence to="izan@sure.im" from="piza@yax.im/Conversations.O-pp" xmlns="jabber:client" xml:lang="en"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" xmlns="http://jabber.org/protocol/caps" node="http://conversations.im" hash="sha-1"/><idle xmlns="urn:xmpp:idle:1" since="2021-09-05T13:32:07.895Z"/><delay from="yax.im" xmlns="urn:xmpp:delay" stamp="2021-09-05T13:32:09Z"/></presence>, SIZE=374, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=REMOTE, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:11.159] [TRACE] [ in_3-message-router] t.s.MessageRouter.processPacket(): 2. Packet will be processed by: sess-man@ip-172-31-20-109.us-west-2.compute.internal, from=s2s@ip-172-31-20-109.us-west-2.compute.internal, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence to="izan@sure.im" from="piza@yax.im/Conversations.O-pp" xmlns="jabber:client" xml:lang="en"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" xmlns="http://jabber.org/protocol/caps" node="http://conversations.im" hash="sha-1"/><idle xmlns="urn:xmpp:idle:1" since="2021-09-05T13:32:07.895Z"/><delay from="yax.im" xmlns="urn:xmpp:delay" stamp="2021-09-05T13:32:09Z"/></presence>, SIZE=374, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=REMOTE, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:11.160] [TRACE] [      in_19-sess-man] t.c.SessionManagerClustered.processPacket(): Received packet: from=s2s@ip-172-31-20-109.us-west-2.compute.internal, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence to="izan@sure.im" from="piza@yax.im/Conversations.O-pp" xmlns="jabber:client" xml:lang="en"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" xmlns="http://jabber.org/protocol/caps" node="http://conversations.im" hash="sha-1"/><idle xmlns="urn:xmpp:idle:1" since="2021-09-05T13:32:07.895Z"/><delay from="yax.im" xmlns="urn:xmpp:delay" stamp="2021-09-05T13:32:09Z"/></presence>, SIZE=374, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=REMOTE, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:11.160] [TRACE] [      in_19-sess-man] t.s.c.s.OnlineUsersCachingStrategy.getNodesForPacketForward(): Selected nodes: [sess-man@ip-172-31-38-91.us-west-2.compute.internal], for packet: from=s2s@ip-172-31-20-109.us-west-2.compute.internal, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence to="izan@sure.im" from="piza@yax.im/Conversations.O-pp" xmlns="jabber:client" xml:lang="en"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" xmlns="http://jabber.org/protocol/caps" node="http://conversations.im" hash="sha-1"/><idle xmlns="urn:xmpp:idle:1" since="2021-09-05T13:32:07.895Z"/><delay from="yax.im" xmlns="urn:xmpp:delay" stamp="2021-09-05T13:32:09Z"/></presence>, SIZE=374, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=REMOTE, TYPE=null, STABLE_ID=e53166b4-ccbb-40fd-8414-efa226f0aa68
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:11.160] [TRACE] [      in_19-sess-man] t.c.s.DefaultClusteringStrategyAbstract.processPacket(): Forwarding packet from=s2s@ip-172-31-20-109.us-west-2.compute.internal, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence to="izan@sure.im" from="piza@yax.im/Conversations.O-pp" xmlns="jabber:client" xml:lang="en"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" xmlns="http://jabber.org/protocol/caps" node="http://conversations.im" hash="sha-1"/><idle xmlns="urn:xmpp:idle:1" since="2021-09-05T13:32:07.895Z"/><delay from="yax.im" xmlns="urn:xmpp:delay" stamp="2021-09-05T13:32:09Z"/></presence>, SIZE=374, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=REMOTE, TYPE=null, STABLE_ID=e53166b4-ccbb-40fd-8414-efa226f0aa68 to nodes: [sess-man@ip-172-31-38-91.us-west-2.compute.internal]
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:11.161] [TRACE] [      in_19-sess-man] t.c.ClusterConnectionManager.executeCommand(): Called fromNode: null, visitedNodes: null, data: null, packets: [<cluster type="set" to="sess-man@ip-172-31-38-91.us-west-2.compute.internal" pr="HIGH" id="cl-402692" from="sess-man@ip-172-31-20-109.us-west-2.compute.internal" xmlns="tigase:cluster"><control><visited-nodes><node-id>sess-man@ip-172-31-20-109.us-west-2.compute.internal</node-id></visited-nodes><method-call name="sess-man-packet-forward-sm-cmd"><par name="user-session-found-key">sess-man@ip-172-31-20-109.us-west-2.compute.internal</par><par name="packet-from">s2s@ip-172-31-20-109.us-west-2.compute.internal</par><par name="stable-id">e53166b4-ccbb-40fd-8414-efa226f0aa68</par></method-call><first-node>sess-man@ip-172-31-20-109.us-west-2.compute.internal</first-node></control><data><presence to="izan@sure.im" from="piza@yax.im/Conversations.O-pp" xmlns="jabber:client" xml:lang="en"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" xmlns="http://jabber.org/protocol/caps" node="http://conversations.im" hash="sha-1"/><idle xmlns="urn:xmpp:idle:1" since="2021-09-05T13:32:07.895Z"/><delay from="yax.im" xmlns="urn:xmpp:delay" stamp="2021-09-05T13:32:09Z"/></presence></data></cluster>]
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:11.161] [TRACE] [      in_19-sess-man] t.c.ClusterElement.<init>()     : Parsing cluster element: <cluster type="set" to="sess-man@ip-172-31-38-91.us-west-2.compute.internal" pr="HIGH" id="cl-402692" from="sess-man@ip-172-31-20-109.us-west-2.compute.internal" xmlns="tigase:cluster"><control><visited-nodes><node-id>sess-man@ip-172-31-20-109.us-west-2.compute.internal</node-id></visited-nodes><method-call name="sess-man-packet-forward-sm-cmd"><par name="user-session-found-key">sess-man@ip-172-31-20-109.us-west-2.compute.internal</par><par name="packet-from">s2s@ip-172-31-20-109.us-west-2.compute.internal</par><par name="stable-id">e53166b4-ccbb-40fd-8414-efa226f0aa68</par></method-call><first-node>sess-man@ip-172-31-20-109.us-west-2.compute.internal</first-node></control><data><presence to="izan@sure.im" from="piza@yax.im/Conversations.O-pp" xmlns="jabber:client" xml:lang="en"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" xmlns="http://jabber.org/protocol/caps" node="http://conversations.im" hash="sha-1"/><idle xmlns="urn:xmpp:idle:1" since="2021-09-05T13:32:07.895Z"/><delay from="yax.im" xmlns="urn:xmpp:delay" stamp="2021-09-05T13:32:09Z"/></presence></data></cluster>
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:11.161] [TRACE] [      in_19-sess-man] t.s.x.SessionManager.processPacket(): processing packet: from=s2s@ip-172-31-20-109.us-west-2.compute.internal, to=sess-man@ip-172-31-20-109.us-west-2.compute.internal, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence to="izan@sure.im" from="piza@yax.im/Conversations.O-pp" xmlns="jabber:client" xml:lang="en"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" xmlns="http://jabber.org/protocol/caps" node="http://conversations.im" hash="sha-1"/><idle xmlns="urn:xmpp:idle:1" since="2021-09-05T13:32:07.895Z"/><delay from="yax.im" xmlns="urn:xmpp:delay" stamp="2021-09-05T13:32:09Z"/></presence>, SIZE=374, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=REMOTE, TYPE=null, STABLE_ID=e53166b4-ccbb-40fd-8414-efa226f0aa68, connection: XMPPResourceConnection=[user_jid=izan@sure.im/Conversations.yDBW, packets=40, connectioId=c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.31.162_61132, domain=sure.im, authState=AUTHORIZED, isAnon=false, isTmp=false, parentSession hash=1493693687, parentSession liveTime=5478]
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:11.161] [TRACE] [        in_5-cl-comp] t.c.ClusterConnectionManager.processPacket(): Processing packet: from=null, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<cluster type="set" to="sess-man@ip-172-31-38-91.us-west-2.compute.internal" pr="HIGH" id="cl-402692" from="sess-man@ip-172-31-20-109.us-west-2.compute.internal" xmlns="tigase:cluster"><control><visited-nodes><node-id>sess-man@ip-172-31-20-109.us-west-2.compute.internal</node-id></visited-nodes><method-call name="sess-man-packet-forward-sm-cmd"><par name="user-session-found-key">sess-man@ip-172-31-20-109.us-west-2.compute.internal</par><par name="packet-from">s2s@ip-172-31-20-109.us-west-2.compute.internal</par><par name="stable-id">e53166b4-ccbb-40fd-8414-efa226f0aa68</par></method-call><first-node>sess-man@ip-172-31-20-109.us-west-2.compute.internal</first-node></control><data><presence to="izan@sure.im" from="piza@yax.im/Conversations.O-pp" xmlns="jabber:client" xml:lang="en"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" xmlns="http://jabber.org/protocol/caps" node="http://conversations.im" hash="sha-1"/><idle xmlns="urn:xmpp:idle:1" since="2021-09-05T13:32:07.895Z"/><delay from="yax.im" xmlns="urn:xmpp:delay" sta ... , SIZE=1079, XMLNS=tigase:cluster, PRIORITY=HIGH, PERMISSION=NONE, TYPE=set, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:11.161] [TRACE] [        in_5-cl-comp] t.c.ClusterElement.<init>()     : Parsing cluster element: <cluster type="set" to="sess-man@ip-172-31-38-91.us-west-2.compute.internal" pr="HIGH" id="cl-402692" from="sess-man@ip-172-31-20-109.us-west-2.compute.internal" xmlns="tigase:cluster"><control><visited-nodes><node-id>sess-man@ip-172-31-20-109.us-west-2.compute.internal</node-id></visited-nodes><method-call name="sess-man-packet-forward-sm-cmd"><par name="user-session-found-key">sess-man@ip-172-31-20-109.us-west-2.compute.internal</par><par name="packet-from">s2s@ip-172-31-20-109.us-west-2.compute.internal</par><par name="stable-id">e53166b4-ccbb-40fd-8414-efa226f0aa68</par></method-call><first-node>sess-man@ip-172-31-20-109.us-west-2.compute.internal</first-node></control><data><presence to="izan@sure.im" from="piza@yax.im/Conversations.O-pp" xmlns="jabber:client" xml:lang="en"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" xmlns="http://jabber.org/protocol/caps" node="http://conversations.im" hash="sha-1"/><idle xmlns="urn:xmpp:idle:1" since="2021-09-05T13:32:07.895Z"/><delay from="yax.im" xmlns="urn:xmpp:delay" stamp="2021-09-05T13:32:09Z"/></presence></data></cluster>
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:11.162] [TRACE] [      in_19-sess-man] t.x.i.DomainFilter.preProcess() : Processing: from=s2s@ip-172-31-20-109.us-west-2.compute.internal, to=sess-man@ip-172-31-20-109.us-west-2.compute.internal, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence to="izan@sure.im" from="piza@yax.im/Conversations.O-pp" xmlns="jabber:client" xml:lang="en"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" xmlns="http://jabber.org/protocol/caps" node="http://conversations.im" hash="sha-1"/><idle xmlns="urn:xmpp:idle:1" since="2021-09-05T13:32:07.895Z"/><delay from="yax.im" xmlns="urn:xmpp:delay" stamp="2021-09-05T13:32:09Z"/></presence>, SIZE=374, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=REMOTE, TYPE=null, STABLE_ID=e53166b4-ccbb-40fd-8414-efa226f0aa68
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:11.162] [TRACE] [        in_5-cl-comp] t.s.ConnectionManager.writePacketToSocket(): Writing packet: from=null, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<cluster type="set" to="sess-man@ip-172-31-38-91.us-west-2.compute.internal" pr="HIGH" id="cl-402692" from="sess-man@ip-172-31-20-109.us-west-2.compute.internal" xmlns="tigase:cluster"><control><visited-nodes><node-id>sess-man@ip-172-31-20-109.us-west-2.compute.internal</node-id></visited-nodes><method-call name="sess-man-packet-forward-sm-cmd"><par name="user-session-found-key">sess-man@ip-172-31-20-109.us-west-2.compute.internal</par><par name="packet-from">s2s@ip-172-31-20-109.us-west-2.compute.internal</par><par name="stable-id">e53166b4-ccbb-40fd-8414-efa226f0aa68</par></method-call><first-node>sess-man@ip-172-31-20-109.us-west-2.compute.internal</first-node></control><data><presence to="izan@sure.im" from="piza@yax.im/Conversations.O-pp" xmlns="jabber:client" xml:lang="en"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" xmlns="http://jabber.org/protocol/caps" node="http://conversations.im" hash="sha-1"/><idle xmlns="urn:xmpp:idle:1" since="2021-09-05T13:32:07.895Z"/><delay from="yax.im" xmlns="urn:xmpp:delay" sta ... , SIZE=1079, XMLNS=tigase:cluster, PRIORITY=HIGH, PERMISSION=NONE, TYPE=set, STABLE_ID=null [jid: ip-172-31-38-91.us-west-2.compute.internal, XMPPIOService, UniqueId: 172.22.0.2_5277_172.31.38.91_52242, type: <- incoming (accept), SocketIO, ID: null, connected Socket[addr=/172.31.38.91,port=52242,localport=5277]]
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:11.162] [TRACE] [      in_19-sess-man] t.s.x.SessionManager.walk()     : XMPPProcessorIfc: MessageAmp (amp)Request: from=s2s@ip-172-31-20-109.us-west-2.compute.internal, to=sess-man@ip-172-31-20-109.us-west-2.compute.internal, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence to="izan@sure.im" from="piza@yax.im/Conversations.O-pp" xmlns="jabber:client" xml:lang="en"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" xmlns="http://jabber.org/protocol/caps" node="http://conversations.im" hash="sha-1"/><idle xmlns="urn:xmpp:idle:1" since="2021-09-05T13:32:07.895Z"/><delay from="yax.im" xmlns="urn:xmpp:delay" stamp="2021-09-05T13:32:09Z"/></presence>, SIZE=374, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=e53166b4-ccbb-40fd-8414-efa226f0aa68, conn: XMPPResourceConnection=[user_jid=izan@sure.im/Conversations.yDBW, packets=41, connectioId=c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.31.162_61132, domain=sure.im, authState=AUTHORIZED, isAnon=false, isTmp=false, parentSession hash=1493693687, parentSession liveTime=5479]
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:11.162] [TRACE] [      in_19-sess-man] t.s.x.SessionManager.walk()     : XMPPProcessorIfc: PepPlugin (pep)Request: from=s2s@ip-172-31-20-109.us-west-2.compute.internal, to=sess-man@ip-172-31-20-109.us-west-2.compute.internal, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence to="izan@sure.im" from="piza@yax.im/Conversations.O-pp" xmlns="jabber:client" xml:lang="en"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" xmlns="http://jabber.org/protocol/caps" node="http://conversations.im" hash="sha-1"/><idle xmlns="urn:xmpp:idle:1" since="2021-09-05T13:32:07.895Z"/><delay from="yax.im" xmlns="urn:xmpp:delay" stamp="2021-09-05T13:32:09Z"/></presence>, SIZE=374, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=e53166b4-ccbb-40fd-8414-efa226f0aa68, conn: XMPPResourceConnection=[user_jid=izan@sure.im/Conversations.yDBW, packets=41, connectioId=c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.31.162_61132, domain=sure.im, authState=AUTHORIZED, isAnon=false, isTmp=false, parentSession hash=1493693687, parentSession liveTime=5479]
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:11.162] [TRACE] [          amp-proc-1] t.x.i.DomainFilter.filter()     : Filtering (packet): from=s2s@ip-172-31-20-109.us-west-2.compute.internal, to=sess-man@ip-172-31-20-109.us-west-2.compute.internal, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence to="izan@sure.im" from="piza@yax.im/Conversations.O-pp" xmlns="jabber:client" xml:lang="en"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" xmlns="http://jabber.org/protocol/caps" node="http://conversations.im" hash="sha-1"/><idle xmlns="urn:xmpp:idle:1" since="2021-09-05T13:32:07.895Z"/><delay from="yax.im" xmlns="urn:xmpp:delay" stamp="2021-09-05T13:32:09Z"/></presence>, SIZE=374, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=e53166b4-ccbb-40fd-8414-efa226f0aa68
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:11.163] [TRACE] [          pep-proc-1] t.x.i.JabberIqPrivacy.filter()  : Checking outbound packet: from=null, to=pubsub@ip-172-31-20-109.us-west-2.compute.internal, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence to="izan@sure.im" from="piza@yax.im/Conversations.O-pp" xmlns="jabber:client" xml:lang="en"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" xmlns="http://jabber.org/protocol/caps" node="http://conversations.im" hash="sha-1"/><idle xmlns="urn:xmpp:idle:1" since="2021-09-05T13:32:07.895Z"/><delay from="yax.im" xmlns="urn:xmpp:delay" stamp="2021-09-05T13:32:09Z"/></presence>, SIZE=374, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:11.163] [TRACE] [          pep-proc-1] t.x.i.MobileV2.filter()         : no session for destination pubsub@ip-172-31-20-109.us-west-2.compute.internal for packet from=null, to=pubsub@ip-172-31-20-109.us-west-2.compute.internal, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence to="izan@sure.im" from="piza@yax.im/Conversations.O-pp" xmlns="jabber:client" xml:lang="en"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" xmlns="http://jabber.org/protocol/caps" node="http://conversations.im" hash="sha-1"/><idle xmlns="urn:xmpp:idle:1" since="2021-09-05T13:32:07.895Z"/><delay from="yax.im" xmlns="urn:xmpp:delay" stamp="2021-09-05T13:32:09Z"/></presence>, SIZE=374, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:11.163] [TRACE] [          pep-proc-1] t.x.i.DomainFilter.filter()     : Filtering (packet): from=s2s@ip-172-31-20-109.us-west-2.compute.internal, to=sess-man@ip-172-31-20-109.us-west-2.compute.internal, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence to="izan@sure.im" from="piza@yax.im/Conversations.O-pp" xmlns="jabber:client" xml:lang="en"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" xmlns="http://jabber.org/protocol/caps" node="http://conversations.im" hash="sha-1"/><idle xmlns="urn:xmpp:idle:1" since="2021-09-05T13:32:07.895Z"/><delay from="yax.im" xmlns="urn:xmpp:delay" stamp="2021-09-05T13:32:09Z"/></presence>, SIZE=374, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=e53166b4-ccbb-40fd-8414-efa226f0aa68
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:11.163] [TRACE] [      in_19-sess-man] t.s.x.SessionManager.walk()     : XMPPProcessorIfc: PresenceState (presence-state)Request: from=s2s@ip-172-31-20-109.us-west-2.compute.internal, to=sess-man@ip-172-31-20-109.us-west-2.compute.internal, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence to="izan@sure.im" from="piza@yax.im/Conversations.O-pp" xmlns="jabber:client" xml:lang="en"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" xmlns="http://jabber.org/protocol/caps" node="http://conversations.im" hash="sha-1"/><idle xmlns="urn:xmpp:idle:1" since="2021-09-05T13:32:07.895Z"/><delay from="yax.im" xmlns="urn:xmpp:delay" stamp="2021-09-05T13:32:09Z"/></presence>, SIZE=374, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=e53166b4-ccbb-40fd-8414-efa226f0aa68, conn: XMPPResourceConnection=[user_jid=izan@sure.im/Conversations.yDBW, packets=41, connectioId=c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.31.162_61132, domain=sure.im, authState=AUTHORIZED, isAnon=false, isTmp=false, parentSession hash=1493693687, parentSession liveTime=5480]
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:11.163] [TRACE] [ in_5-message-router] t.s.MessageRouter.processPacket(): Processing packet: from=sess-man@ip-172-31-20-109.us-west-2.compute.internal, to=pubsub@ip-172-31-20-109.us-west-2.compute.internal, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence to="izan@sure.im" from="piza@yax.im/Conversations.O-pp" xmlns="jabber:client" xml:lang="en"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" xmlns="http://jabber.org/protocol/caps" node="http://conversations.im" hash="sha-1"/><idle xmlns="urn:xmpp:idle:1" since="2021-09-05T13:32:07.895Z"/><delay from="yax.im" xmlns="urn:xmpp:delay" stamp="2021-09-05T13:32:09Z"/></presence>, SIZE=374, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:11.163] [TRACE] [presence-state-proc-1] t.x.i.PresenceState.process()  : izan@sure.im | in_initial presence found: from=s2s@ip-172-31-20-109.us-west-2.compute.internal, to=sess-man@ip-172-31-20-109.us-west-2.compute.internal, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence to="izan@sure.im" from="piza@yax.im/Conversations.O-pp" xmlns="jabber:client" xml:lang="en"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" xmlns="http://jabber.org/protocol/caps" node="http://conversations.im" hash="sha-1"/><idle xmlns="urn:xmpp:idle:1" since="2021-09-05T13:32:07.895Z"/><delay from="yax.im" xmlns="urn:xmpp:delay" stamp="2021-09-05T13:32:09Z"/></presence>, SIZE=374, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=e53166b4-ccbb-40fd-8414-efa226f0aa68
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:11.164] [TRACE] [presence-state-proc-1] t.x.i.JabberIqPrivacy.filter() : Checking outbound packet: from=null, to=c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.31.162_61132, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence to="izan@sure.im" from="piza@yax.im/Conversations.O-pp" xmlns="jabber:client" xml:lang="en"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" xmlns="http://jabber.org/protocol/caps" node="http://conversations.im" hash="sha-1"/><idle xmlns="urn:xmpp:idle:1" since="2021-09-05T13:32:07.895Z"/><delay from="yax.im" xmlns="urn:xmpp:delay" stamp="2021-09-05T13:32:09Z"/></presence>, SIZE=374, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:11.164] [TRACE] [presence-state-proc-1] t.x.i.MobileV2.filter()        : checking if packet should be queued from=null, to=c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.31.162_61132, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence to="izan@sure.im" from="piza@yax.im/Conversations.O-pp" xmlns="jabber:client" xml:lang="en"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" xmlns="http://jabber.org/protocol/caps" node="http://conversations.im" hash="sha-1"/><idle xmlns="urn:xmpp:idle:1" since="2021-09-05T13:32:07.895Z"/><delay from="yax.im" xmlns="urn:xmpp:delay" stamp="2021-09-05T13:32:09Z"/></presence>, SIZE=374, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:11.164] [TRACE] [ in_5-message-router] t.s.MessageRouter.processPacket(): 1. Packet will be processed by: pubsub@ip-172-31-20-109.us-west-2.compute.internal, from=sess-man@ip-172-31-20-109.us-west-2.compute.internal, to=pubsub@ip-172-31-20-109.us-west-2.compute.internal, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence to="izan@sure.im" from="piza@yax.im/Conversations.O-pp" xmlns="jabber:client" xml:lang="en"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" xmlns="http://jabber.org/protocol/caps" node="http://conversations.im" hash="sha-1"/><idle xmlns="urn:xmpp:idle:1" since="2021-09-05T13:32:07.895Z"/><delay from="yax.im" xmlns="urn:xmpp:delay" stamp="2021-09-05T13:32:09Z"/></presence>, SIZE=374, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:11.164] [TRACE] [presence-state-proc-1] t.x.i.MobileV2.filter()        : queuing packet from=null, to=c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.31.162_61132, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence to="izan@sure.im" from="piza@yax.im/Conversations.O-pp" xmlns="jabber:client" xml:lang="en"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" xmlns="http://jabber.org/protocol/caps" node="http://conversations.im" hash="sha-1"/><idle xmlns="urn:xmpp:idle:1" since="2021-09-05T13:32:07.895Z"/><delay from="yax.im" xmlns="urn:xmpp:delay" stamp="2021-09-05T13:32:09Z"/></presence>, SIZE=374, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:11.164] [TRACE] [presence-state-proc-1] t.x.i.MobileV2.filter()        : queuing packet = from=null, to=c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.31.162_61132, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence to="izan@sure.im" from="piza@yax.im/Conversations.O-pp" xmlns="jabber:client" xml:lang="en"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" xmlns="http://jabber.org/protocol/caps" node="http://conversations.im" hash="sha-1"/><idle xmlns="urn:xmpp:idle:1" since="2021-09-05T13:32:07.895Z"/><delay from="yax.im" xmlns="urn:xmpp:delay" stamp="2021-09-05T13:32:09Z"/></presence>, SIZE=374, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:11.164] [TRACE] [presence-state-proc-1] t.x.i.DomainFilter.filter()    : Filtering (packet): from=s2s@ip-172-31-20-109.us-west-2.compute.internal, to=sess-man@ip-172-31-20-109.us-west-2.compute.internal, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence to="izan@sure.im" from="piza@yax.im/Conversations.O-pp" xmlns="jabber:client" xml:lang="en"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" xmlns="http://jabber.org/protocol/caps" node="http://conversations.im" hash="sha-1"/><idle xmlns="urn:xmpp:idle:1" since="2021-09-05T13:32:07.895Z"/><delay from="yax.im" xmlns="urn:xmpp:delay" stamp="2021-09-05T13:32:09Z"/></presence>, SIZE=374, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=e53166b4-ccbb-40fd-8414-efa226f0aa68
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:26:11.166] [TRACE] [      in_19-sess-man] t.x.i.DomainFilter.filter()     : Filtering (packet): from=s2s@ip-172-31-20-109.us-west-2.compute.internal, to=sess-man@ip-172-31-20-109.us-west-2.compute.internal, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence to="izan@sure.im" from="piza@yax.im/Conversations.O-pp" xmlns="jabber:client" xml:lang="en"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" xmlns="http://jabber.org/protocol/caps" node="http://conversations.im" hash="sha-1"/><idle xmlns="urn:xmpp:idle:1" since="2021-09-05T13:32:07.895Z"/><delay from="yax.im" xmlns="urn:xmpp:delay" stamp="2021-09-05T13:32:09Z"/></presence>, SIZE=374, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=AUTH, TYPE=null, STABLE_ID=e53166b4-ccbb-40fd-8414-efa226f0aa68
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:29:37.121] [TRACE] [            in_2-c2s] t.s.x.StreamManagementIOProcessor.processCommand(): resuming stream with id = 758ce683-de8d-4d68-8ffa-4cf2c9764127 resending unacked packet = from=null, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/><delay from="ip-172-31-20-109.us-west-2.compute.internal" xmlns="urn:xmpp:delay" stamp="2021-09-05T15:26:10.842Z"/></presence>, SIZE=384, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null [jid: izan@sure.im/Conversations.yDBW, C2SIOService, UniqueId: 172.22.0.2_5223_172.31.31.162_61132, type: <- incoming (accept), TLS: SocketIO, ID: c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.31.162_61132, connected Socket[addr=/172.31.31.162,port=61132,localport=5223]]
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:29:37.121] [TRACE] [            in_2-c2s] t.s.x.StreamManagementIOProcessor.processOutgoing(): Queuing StreamManagement packet: from=null, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/><delay from="ip-172-31-20-109.us-west-2.compute.internal" xmlns="urn:xmpp:delay" stamp="2021-09-05T15:26:10.842Z"/></presence>, SIZE=384, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null, queue size: 19 [jid: izan@sure.im/Conversations.yDBW, C2SIOService, UniqueId: 172.22.0.2_5223_172.31.10.118_35718, type: <- incoming (accept), TLS: SocketIO, ID: c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.10.118_35718, connected Socket[addr=/172.31.10.118,port=35718,localport=5223]]
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:38:29.437] [TRACE] [    pool-35-thread-8] t.c.ClusterElement.<init>()     : Parsing cluster element: <cluster type="set" to="sess-man@ip-172-31-20-109.us-west-2.compute.internal" pr="CLUSTER" id="cl-113816" from="sess-man@ip-172-31-0-99.us-west-2.compute.internal" xmlns="tigase:cluster"><control><visited-nodes><node-id>sess-man@ip-172-31-0-99.us-west-2.compute.internal</node-id></visited-nodes><method-call name="sess-man-user-presence-sm-cmd"><par name="userId">izan@sure.im</par><par name="resource">Conversations.yDBW</par><par name="connId">c2s@ip-172-31-0-99.us-west-2.compute.internal/172.22.0.2_5223_172.31.42.200_4880</par><par name="xmppSessId">2dc3564e-fd01-4e96-b1fc-ab4085f7505d</par><par name="auth-time">380</par><par name="creation-t">1630856303092</par><par name="login_t">380</par><par name="pres-type">initial</par></method-call><first-node>sess-man@ip-172-31-0-99.us-west-2.compute.internal</first-node></control><data><presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence></data></cluster>
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:38:29.438] [TRACE] [       out_5-cl-comp] t.c.ClusterElement.<init>()     : Parsing cluster element: <cluster type="set" to="sess-man@ip-172-31-20-109.us-west-2.compute.internal" pr="CLUSTER" id="cl-113816" from="sess-man@ip-172-31-0-99.us-west-2.compute.internal" xmlns="tigase:cluster"><control><visited-nodes><node-id>sess-man@ip-172-31-0-99.us-west-2.compute.internal</node-id></visited-nodes><method-call name="sess-man-user-presence-sm-cmd"><par name="userId">izan@sure.im</par><par name="resource">Conversations.yDBW</par><par name="connId">c2s@ip-172-31-0-99.us-west-2.compute.internal/172.22.0.2_5223_172.31.42.200_4880</par><par name="xmppSessId">2dc3564e-fd01-4e96-b1fc-ab4085f7505d</par><par name="auth-time">380</par><par name="creation-t">1630856303092</par><par name="login_t">380</par><par name="pres-type">initial</par></method-call><first-node>sess-man@ip-172-31-0-99.us-west-2.compute.internal</first-node></control><data><presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence></data></cluster>
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:38:29.438] [TRACE] [       out_5-cl-comp] t.s.c.s.c.UserPresenceCmd.executeCommand(): Called fromNode: sess-man@ip-172-31-0-99.us-west-2.compute.internal, visitedNodes: [sess-man@ip-172-31-0-99.us-west-2.compute.internal, sess-man@ip-172-31-20-109.us-west-2.compute.internal], data: {userId=izan@sure.im, resource=Conversations.yDBW, connId=c2s@ip-172-31-0-99.us-west-2.compute.internal/172.22.0.2_5223_172.31.42.200_4880, xmppSessId=2dc3564e-fd01-4e96-b1fc-ab4085f7505d, auth-time=380, creation-t=1630856303092, login_t=380, pres-type=initial}, packets: [<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>]
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:38:29.438] [TRACE] [ in_3-message-router] t.s.MessageRouter.processPacket(): Processing packet: from=sess-man@ip-172-31-20-109.us-west-2.compute.internal, to=c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.10.118_35718, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence to="izan@sure.im/Conversations.yDBW" from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=306, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:38:29.438] [TRACE] [     pool-1-thread-4] t.x.i.MessageCarbons.presenceUpdate(): session = XMPPSession=[hash=1493693687, username: izan, resources: [XMPPResourceConnection=[user_jid=izan@sure.im/Conversations.yDBW, packets=186, connectioId=c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.10.118_35718, domain=sure.im, authState=AUTHORIZED, isAnon=false, isTmp=false, parentSession hash=1493693687, parentSession liveTime=743755]]]; processing presence = from=null, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=269, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:38:29.439] [TRACE] [ in_6-message-router] t.s.MessageRouter.processPacket(): Processing packet: from=sess-man@ip-172-31-20-109.us-west-2.compute.internal, to=c2s@ip-172-31-0-99.us-west-2.compute.internal/172.22.0.2_5223_172.31.42.200_4880, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=269, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:38:29.440] [TRACE] [ in_6-message-router] t.s.MessageRouter.processPacket(): 2. Packet will be processed by: cl-comp@ip-172-31-20-109.us-west-2.compute.internal, from=sess-man@ip-172-31-20-109.us-west-2.compute.internal, to=c2s@ip-172-31-0-99.us-west-2.compute.internal/172.22.0.2_5223_172.31.42.200_4880, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=269, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:38:29.441] [TRACE] [        in_6-cl-comp] t.c.ClusterConnectionManager.processPacket(): Processing packet: from=sess-man@ip-172-31-20-109.us-west-2.compute.internal, to=c2s@ip-172-31-0-99.us-west-2.compute.internal/172.22.0.2_5223_172.31.42.200_4880, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=269, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:38:29.441] [TRACE] [        in_6-cl-comp] t.s.ConnectionManager.writePacketToSocket(): Writing packet: from=null, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<route from="sess-man@ip-172-31-20-109.us-west-2.compute.internal" to="c2s@ip-172-31-0-99.us-west-2.compute.internal/172.22.0.2_5223_172.31.42.200_4880" pr="PRESENCE" perm="NONE"><presence from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence></route>, SIZE=456, XMLNS=null, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=null, STABLE_ID=null [jid: ip-172-31-0-99.us-west-2.compute.internal, XMPPIOService, UniqueId: 172.22.0.2_5277_172.31.0.99_34672, type: <- incoming (accept), SocketIO, ID: null, connected Socket[addr=/172.31.0.99,port=34672,localport=5277]]
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:38:29.441] [TRACE] [ in_3-message-router] t.s.MessageRouter.processPacket(): 1. Packet will be processed by: c2s@ip-172-31-20-109.us-west-2.compute.internal, from=sess-man@ip-172-31-20-109.us-west-2.compute.internal, to=c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.10.118_35718, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence to="izan@sure.im/Conversations.yDBW" from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=306, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:38:29.441] [TRACE] [            in_3-c2s] t.s.x.ClientConnectionManager.processPacket(): Processing packet: from=sess-man@ip-172-31-20-109.us-west-2.compute.internal, to=c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.10.118_35718, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence to="izan@sure.im/Conversations.yDBW" from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=306, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:38:29.442] [TRACE] [            in_3-c2s] t.s.ConnectionManager.writePacketToSocket(): Writing packet: from=sess-man@ip-172-31-20-109.us-west-2.compute.internal, to=c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.10.118_35718, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence to="izan@sure.im/Conversations.yDBW" from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=306, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null [jid: izan@sure.im/Conversations.yDBW, C2SIOService, UniqueId: 172.22.0.2_5223_172.31.10.118_35718, type: <- incoming (accept), TLS: SocketIO, ID: c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.10.118_35718, disconnected Socket[addr=/172.31.10.118,port=35718,localport=5223]]
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:38:29.442] [TRACE] [            in_3-c2s] t.s.x.StreamManagementIOProcessor.processOutgoing(): Queuing StreamManagement packet: from=sess-man@ip-172-31-20-109.us-west-2.compute.internal, to=c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.10.118_35718, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence to="izan@sure.im/Conversations.yDBW" from="izan@sure.im/Conversations.yDBW" xmlns="jabber:client"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" node="http://conversations.im" xmlns="http://jabber.org/protocol/caps" hash="sha-1"/><idle since="2021-09-05T13:32:07.895Z" xmlns="urn:xmpp:idle:1"/></presence>, SIZE=306, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null, queue size: 40 [jid: izan@sure.im/Conversations.yDBW, C2SIOService, UniqueId: 172.22.0.2_5223_172.31.10.118_35718, type: <- incoming (accept), TLS: SocketIO, ID: c2s@ip-172-31-20-109.us-west-2.compute.internal/172.22.0.2_5223_172.31.10.118_35718, disconnected Socket[addr=/172.31.10.118,port=35718,localport=5223]]
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:38:29.641] [TRACE] [    pool-35-thread-9] t.s.x.S2SConnectionManager.processSocketData(): Processing socket data: from=null, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence to="izan@sure.im" from="piza@yax.im/Conversations.O-pp" xml:lang="en"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" xmlns="http://jabber.org/protocol/caps" node="http://conversations.im" hash="sha-1"/><idle xmlns="urn:xmpp:idle:1" since="2021-09-05T13:32:07.895Z"/><delay from="yax.im" xmlns="urn:xmpp:delay" stamp="2021-09-05T13:32:09Z"/></presence>, SIZE=352, XMLNS=null, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null [CID: sure.im@yax.im, IN: 1, OUT: 1, authenticated: true, remote-session-id: a2716322-c2a8-4ebd-8507-6cdb8418a797, jid: null, S2SIOService, UniqueId: 172.22.0.2_5269_172.31.10.118_52600, type: <- incoming (accept), TLS: SocketIO, ID: sure.im@yax.im/33b36cba-dc80-42fc-872e-00f45e5c0643, connected Socket[addr=/172.31.10.118,port=52600,localport=5269]]
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:38:29.641] [DEBUG] [    pool-35-thread-9] t.s.x.p.AuthenticatorSelectorManager.isAllowed(): Connection already authenticated, skipping processor: tigase.server.xmppserver.proc.SaslExternal@1c71d704, methodsAvailable: [tigase.server.xmppserver.proc.SaslExternal@1c71d704, tigase.server.xmppserver.proc.Dialback@d5d9d92], checking packet: from=null, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence to="izan@sure.im" from="piza@yax.im/Conversations.O-pp" xmlns="jabber:server" xml:lang="en"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" xmlns="http://jabber.org/protocol/caps" node="http://conversations.im" hash="sha-1"/><idle xmlns="urn:xmpp:idle:1" since="2021-09-05T13:32:07.895Z"/><delay from="yax.im" xmlns="urn:xmpp:delay" stamp="2021-09-05T13:32:09Z"/></presence>, SIZE=374, XMLNS=jabber:server, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null [CID: sure.im@yax.im, IN: 1, OUT: 1, authenticated: true, remote-session-id: a2716322-c2a8-4ebd-8507-6cdb8418a797, jid: null, S2SIOService, UniqueId: 172.22.0.2_5269_172.31.10.118_52600, type: <- incoming (accept), TLS: SocketIO, ID: sure.im@yax.im/33b36cba-dc80-42fc-872e-00f45e5c0643, connected Socket[addr=/172.31.10.118,port=52600,localport=5269]]
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:38:29.641] [DEBUG] [    pool-35-thread-9] t.s.x.p.AuthenticatorSelectorManager.isAllowed(): Connection already authenticated, skipping processor: tigase.server.xmppserver.proc.Dialback@d5d9d92, methodsAvailable: [tigase.server.xmppserver.proc.SaslExternal@1c71d704, tigase.server.xmppserver.proc.Dialback@d5d9d92], checking packet: from=null, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence to="izan@sure.im" from="piza@yax.im/Conversations.O-pp" xmlns="jabber:server" xml:lang="en"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" xmlns="http://jabber.org/protocol/caps" node="http://conversations.im" hash="sha-1"/><idle xmlns="urn:xmpp:idle:1" since="2021-09-05T13:32:07.895Z"/><delay from="yax.im" xmlns="urn:xmpp:delay" stamp="2021-09-05T13:32:09Z"/></presence>, SIZE=374, XMLNS=jabber:server, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null [CID: sure.im@yax.im, IN: 1, OUT: 1, authenticated: true, remote-session-id: a2716322-c2a8-4ebd-8507-6cdb8418a797, jid: null, S2SIOService, UniqueId: 172.22.0.2_5269_172.31.10.118_52600, type: <- incoming (accept), TLS: SocketIO, ID: sure.im@yax.im/33b36cba-dc80-42fc-872e-00f45e5c0643, connected Socket[addr=/172.31.10.118,port=52600,localport=5269]]
tigase.logback.2021-09-05.17.log.gz:[2021-09-05 15:38:29.641] [TRACE] [    pool-35-thread-9] t.s.x.S2SConnectionManager.processSocketData(): Adding packet out: from=null, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence to="izan@sure.im" from="piza@yax.im/Conversations.O-pp" xmlns="jabber:client" xml:lang="en"><c ver="KWQQsqlerqQGIyKLIQTBsn7Adho=" xmlns="http://jabber.org/protocol/caps" node="http://conversations.im" hash="sha-1"/><idle xmlns="urn:xmpp:idle:1" since="2021-09-05T13:32:07.895Z"/><delay from="yax.im" xmlns="urn:xmpp:delay" stamp="2021-09-05T13:32:09Z"/></presence>, SIZE=374, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null, STABLE_ID=null [CID: sure.im@yax.im, IN: 1, OUT: 1, authenticated: true, remote-session-id: a2716322-c2a8-4ebd-8507-6cdb8418a797, jid: null, S2SIOService, UniqueId: 172.22.0.2_5269_172.31.10.118_52600, type: <- incoming (accept), TLS: SocketIO, ID: sure.im@yax.im/33b36cba-dc80-42fc-872e-00f45e5c0643, connected Socket[addr=/172.31.10.118,port=52600,localport=5269]]
tigase.logback.2021-09-05.17....

Wojciech Kapcia (Tigase) commented 4 years ago

Thank you for your comments Andrzej, merged.
Login to comment

Type	Bug
Priority	Normal
Assignee	Wojciech Kapcia (Tigase)
Version	tigase-server-8.2.0
Spent time	0

Issue Votes (0)

Watchers (0)

Reference

tigase/_server/server-core#1188