UserNotFoundException in SessionManagerClustered.handleLogout (#1250)

Wojciech Kapcia (Tigase) opened 4 years ago

StackTraces:

[2021-04-22 20:56:06:990] [FINEST  ] [jabber:iq:register-proc-0 ] RepositoryAccess.setData()    : Problem accessing reposiotry: 
tigase.db.UserNotFoundException: User does not exist: …@tigase.im
	at tigase.db.jdbc.JDBCRepository.getUserUID(JDBCRepository.java:1195)
	at tigase.db.jdbc.JDBCRepository.setData(JDBCRepository.java:650)
	at jdk.internal.reflect.GeneratedMethodAccessor103.invoke(Unknown Source)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
	at java.base/java.lang.reflect.Method.invoke(Unknown Source)
	at tigase.stats.StatisticsInvocationHandler.invoke(StatisticsInvocationHandler.java:75)
	at com.sun.proxy.$Proxy44.setData(Unknown Source)
	at tigase.db.UserRepositoryMDImpl.setData(UserRepositoryMDImpl.java:341)
	at tigase.xmpp.RepositoryAccess.setData(RepositoryAccess.java:470)
	at tigase.xmpp.impl.roster.RosterFlat.saveUserRoster(RosterFlat.java:597)
	at tigase.xmpp.impl.roster.RosterFlat.logout(RosterFlat.java:524)
	at tigase.xmpp.impl.PresenceState.stopped(PresenceState.java:471)
	at tigase.server.xmppsession.SessionManager.closeSession(SessionManager.java:967)
	at tigase.cluster.SessionManagerClustered.closeSession(SessionManagerClustered.java:491)
	at tigase.server.xmppsession.SessionManager.handleLogout(SessionManager.java:355)
	at tigase.cluster.SessionManagerClustered.handleLogout(SessionManagerClustered.java:173)
	at tigase.xmpp.XMPPResourceConnection.logout(XMPPResourceConnection.java:191)
	at tigase.xmpp.impl.JabberIqRegister.doRemoveAccount(JabberIqRegister.java:540)
	at tigase.xmpp.impl.JabberIqRegister.process(JabberIqRegister.java:336)
	at tigase.server.xmppsession.SessionManager$ProcessorWorkerThread.process(SessionManager.java:2656)
	at tigase.util.processing.WorkerThread.run(WorkerThread.java:67)

[2021-04-22 20:56:06:992] [WARNING ] [jabber:iq:register-proc-0 ] RosterFlat.logout()           : Error logging out user
tigase.xmpp.NotAuthorizedException: Can not access user repository.
	at tigase.xmpp.RepositoryAccess.setData(RepositoryAccess.java:474)
	at tigase.xmpp.impl.roster.RosterFlat.saveUserRoster(RosterFlat.java:597)
	at tigase.xmpp.impl.roster.RosterFlat.logout(RosterFlat.java:524)
	at tigase.xmpp.impl.PresenceState.stopped(PresenceState.java:471)
	at tigase.server.xmppsession.SessionManager.closeSession(SessionManager.java:967)
	at tigase.cluster.SessionManagerClustered.closeSession(SessionManagerClustered.java:491)
	at tigase.server.xmppsession.SessionManager.handleLogout(SessionManager.java:355)
	at tigase.cluster.SessionManagerClustered.handleLogout(SessionManagerClustered.java:173)
	at tigase.xmpp.XMPPResourceConnection.logout(XMPPResourceConnection.java:191)
	at tigase.xmpp.impl.JabberIqRegister.doRemoveAccount(JabberIqRegister.java:540)
	at tigase.xmpp.impl.JabberIqRegister.process(JabberIqRegister.java:336)
	at tigase.server.xmppsession.SessionManager$ProcessorWorkerThread.process(SessionManager.java:2656)
	at tigase.util.processing.WorkerThread.run(WorkerThread.java:67)
Caused by: tigase.db.UserNotFoundException: User does not exist: …@tigase.im
	at tigase.db.jdbc.JDBCRepository.getUserUID(JDBCRepository.java:1195)
	at tigase.db.jdbc.JDBCRepository.setData(JDBCRepository.java:650)
	at jdk.internal.reflect.GeneratedMethodAccessor103.invoke(Unknown Source)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
	at java.base/java.lang.reflect.Method.invoke(Unknown Source)
	at tigase.stats.StatisticsInvocationHandler.invoke(StatisticsInvocationHandler.java:75)
	at com.sun.proxy.$Proxy44.setData(Unknown Source)
	at tigase.db.UserRepositoryMDImpl.setData(UserRepositoryMDImpl.java:341)
	at tigase.xmpp.RepositoryAccess.setData(RepositoryAccess.java:470)
	... 12 more

Comments:

it looks like the account was removed on one node and then due to concurrency exception was thrown on another
It seems, that at the least just changing log level should be enough as this doesn't seem essential to system operation.

Activities

Wojciech Kapcia (Tigase) commented 4 years ago

More complete log:

[2021-04-22 20:56:06:984] [FINEST  ] [jabber:iq:register-proc-0 ] MessageCarbons.presenceUpdate(): session = XMPPSession=[hash=1178437590, username: busoft1, resources: [XMPPResourceConnection=[user_jid=busoft1@tigase.im/Hamza’s iPhone, packets=44, connectioId=c2s@ip-172-31-38-91.us-west-2.compute.internal/172.19.0.2_5222_46.221.117.18_3024, domain=tigase.im, authState=AUTHORIZED, isAnon=false, isTmp=false, parentSession hash=1178437590, parentSession liveTime=33551]]]; processing presence = from=null, to=null, DATA=<presence xmlns="jabber:client" from="busoft1@tigase.im/Hamza’s iPhone" type="unavailable"><c hash="sha-1" xmlns="http://jabber.org/protocol/caps" node="http://tigase.org/TigaseSwiftX" ver="+qMgYHw6R303EDP6b7JlUN1I0HA="/><priority>5</priority></presence>, SIZE=254, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=unavailable, STABLE_ID=null
[2021-04-22 20:56:06:984] [FINER   ] [jabber:iq:register-proc-0 ] MessageCarbons.presenceUpdate(): session = XMPPSession=[hash=1178437590, username: busoft1, resources: [XMPPResourceConnection=[user_jid=busoft1@tigase.im/Hamza’s iPhone, packets=44, connectioId=c2s@ip-172-31-38-91.us-west-2.compute.internal/172.19.0.2_5222_46.221.117.18_3024, domain=tigase.im, authState=AUTHORIZED, isAnon=false, isTmp=false, parentSession hash=1178437590, parentSession liveTime=33551]]]; removing resource = busoft1@tigase.im/Hamza’s iPhone from list of available resources
[2021-04-22 20:56:06:984] [FINEST  ] [jabber:iq:register-proc-0 ] PresenceState.broadcastDirectPresences(): Updating direct presence for: 69F9BD42-27DE-42F4-BE80-2649E1FC7AE3@muc.tigase.im/busoft1
[2021-04-22 20:56:06:984] [FINEST  ] [jabber:iq:register-proc-0 ] XMPPIOService.processWaitingPackets(): SENT: <cluster id="cl-6640996" xmlns="tigase:cluster" from="sess-man@ip-172-31-38-91.us-west-2.compute.internal" to="sess-man@ip-172-31-20-109.us-west-2.compute.internal" type="set" pr="CLUSTER"><control><visited-nodes><node-id>sess-man@ip-172-31-38-91.us-west-2.compute.internal</node-id></visited-nodes><method-call name="sess-man-user-disconnected-sm-cmd"><par name="userId">busoft1@tigase.im</par><par name="resource">Hamza’s iPhone</par><par name="connId">c2s@ip-172-31-38-91.us-west-2.compute.internal/172.19.0.2_5222_46.221.117.18_3024</par><par name="xmppSessId">b85b83d4-6ed1-4d25-b236-b8f32919d876</par><par name="auth-time">2081</par><par name="creation-t">1619124957887</par><par name="login_t">2081</par></method-call><first-node>sess-man@ip-172-31-38-91.us-west-2.compute.internal</first-node></control><data><presence xmlns="jabber:client" from="busoft1@tigase.im/Hamza’s iPhone" type="unavailable"><c hash="sha-1" xmlns="http://jabber.org/protocol/caps" node="http://tigase.org/TigaseSwiftX" ver="+qMgYHw6R303EDP6b7JlUN1I0HA="/><priority>5</priority></presence></data></cluster> [jid: ip-172-31-20-109.us-west-2.compute.internal, XMPPIOService, UniqueId: 172.19.0.2_5277_172.31.20.109_35490, type: <- incoming (accept), SocketIO, ID: null, connected Socket[addr=/172.31.20.109,port=35490,localport=5277]]
[2021-04-22 20:56:06:985] [FINEST  ] [jabber:iq:register-proc-0 ] PresenceAbstract.sendPresence(): Sending presence info: from=null, to=null, DATA=<presence to="69F9BD42-27DE-42F4-BE80-2649E1FC7AE3@muc.tigase.im/busoft1" xmlns="jabber:client" from="busoft1@tigase.im/Hamza’s iPhone" type="unavailable"><c hash="sha-1" xmlns="http://jabber.org/protocol/caps" node="http://tigase.org/TigaseSwiftX" ver="+qMgYHw6R303EDP6b7JlUN1I0HA="/><priority>5</priority></presence>, SIZE=318, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=unavailable, STABLE_ID=null
[2021-04-22 20:56:06:985] [FINEST  ] [jabber:iq:register-proc-0 ] SocketThread.addSocketServicePriv(): Adding to waiting: jid: ip-172-31-20-109.us-west-2.compute.internal, XMPPIOService, UniqueId: 172.19.0.2_5277_172.31.20.109_35490, type: <- incoming (accept), SocketIO, ID: null, connected Socket[addr=/172.31.20.109,port=35490,localport=5277]
[2021-04-22 20:56:06:985] [FINEST  ] [jabber:iq:register-proc-0 ] SocketThread.run()            : Selector AWAKE: sun.nio.ch.EPollSelectorImpl@7e8cccfd
[2021-04-22 20:56:06:985] [FINEST  ] [jabber:iq:register-proc-0 ] SocketThread.addAllWaiting()  : waiting.size(): 1
[2021-04-22 20:56:06:985] [FINEST  ] [jabber:iq:register-proc-0 ] SocketThread.addAllWaiting()  : ADDED OP_READ: SocketIO, ID: null, connected Socket[addr=/172.31.20.109,port=35490,localport=5277]
[2021-04-22 20:56:06:985] [FINEST  ] [jabber:iq:register-proc-0 ] PresenceState.sendPresenceBroadcast(): busoft1@tigase.im | Buddies found: [ferhatbalaban@tigase.im, suleyman@tigase.im, busoft2@tigase.im]
[2021-04-22 20:56:06:985] [FINEST  ] [jabber:iq:register-proc-0 ] SessionManagerClustered.containsJid(): Called for jid: ferhatbalaban@tigase.im
[2021-04-22 20:56:06:985] [FINEST  ] [jabber:iq:register-proc-0 ] PresenceAbstract.sendPresence(): Sending presence info: from=null, to=null, DATA=<presence to="ferhatbalaban@tigase.im" xmlns="jabber:client" from="busoft1@tigase.im/Hamza’s iPhone" type="unavailable"><c hash="sha-1" xmlns="http://jabber.org/protocol/caps" node="http://tigase.org/TigaseSwiftX" ver="+qMgYHw6R303EDP6b7JlUN1I0HA="/><priority>5</priority></presence>, SIZE=283, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=unavailable, STABLE_ID=null
[2021-04-22 20:56:06:986] [FINEST  ] [jabber:iq:register-proc-0 ] SessionManagerClustered.containsJid(): Called for jid: suleyman@tigase.im
[2021-04-22 20:56:06:986] [FINEST  ] [jabber:iq:register-proc-0 ] PresenceAbstract.sendPresence(): Sending presence info: from=null, to=null, DATA=<presence to="suleyman@tigase.im" xmlns="jabber:client" from="busoft1@tigase.im/Hamza’s iPhone" type="unavailable"><c hash="sha-1" xmlns="http://jabber.org/protocol/caps" node="http://tigase.org/TigaseSwiftX" ver="+qMgYHw6R303EDP6b7JlUN1I0HA="/><priority>5</priority></presence>, SIZE=278, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=unavailable, STABLE_ID=null
[2021-04-22 20:56:06:986] [FINEST  ] [jabber:iq:register-proc-0 ] SessionManagerClustered.containsJid(): Called for jid: busoft2@tigase.im
[2021-04-22 20:56:06:986] [FINEST  ] [jabber:iq:register-proc-0 ] PresenceAbstract.sendPresence(): Sending presence info: from=null, to=null, DATA=<presence to="busoft2@tigase.im" xmlns="jabber:client" from="busoft1@tigase.im/Hamza’s iPhone" type="unavailable"><c hash="sha-1" xmlns="http://jabber.org/protocol/caps" node="http://tigase.org/TigaseSwiftX" ver="+qMgYHw6R303EDP6b7JlUN1I0HA="/><priority>5</priority></presence>, SIZE=277, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=unavailable, STABLE_ID=null
[2021-04-22 20:56:06:986] [FINER   ] [jabber:iq:register-proc-0 ] PresenceState.updateOfflineChange(): Update presence change to: busoft1@tigase.im/Hamza’s iPhone
[2021-04-22 20:56:06:986] [FINER   ] [jabber:iq:register-proc-0 ] PresenceState.updateOfflineChange(): Skipping presence update to: busoft1@tigase.im/Hamza’s iPhone
[2021-04-22 20:56:06:986] [FINEST  ] [jabber:iq:register-proc-0 ] RosterFlat.saveUserRoster()   : busoft1@tigase.im | Saving user roster: <contact last-seen="1619124961224" preped="simple" weight="1.0" name="ferhatbalaban" activity="1.0" subs="both" jid="ferhatbalaban@tigase.im"/><contact last-seen="1619124961401" preped="simple" weight="1.0" name="suleyman" activity="1.0" subs="both" jid="suleyman@tigase.im"/><contact last-seen="1000" preped="simple" weight="1.0" name="busoft2" activity="1.0" subs="from_pending_out" jid="busoft2@tigase.im"/>
[2021-04-22 20:56:06:985] [FINEST  ] [jabber:iq:register-proc-0 ] ClusterConnectionManager.processPacket(): Processing packet: from=null, to=null, DATA=<cluster id="cl-6640997" xmlns="tigase:cluster" from="sess-man@ip-172-31-38-91.us-west-2.compute.internal" to="sess-man@ip-172-31-0-99.us-west-2.compute.internal" type="set" pr="CLUSTER"><control><visited-nodes><node-id>sess-man@ip-172-31-38-91.us-west-2.compute.internal</node-id></visited-nodes><method-call name="sess-man-user-disconnected-sm-cmd"><par name="userId">busoft1@tigase.im</par><par name="resource">Hamza’s iPhone</par><par name="connId">c2s@ip-172-31-38-91.us-west-2.compute.internal/172.19.0.2_5222_46.221.117.18_3024</par><par name="xmppSessId">b85b83d4-6ed1-4d25-b236-b8f32919d876</par><par name="auth-time">2081</par><par name="creation-t">1619124957887</par><par name="login_t">2081</par></method-call><first-node>sess-man@ip-172-31-38-91.us-west-2.compute.internal</first-node></control><data><presence xmlns="jabber:client" from="busoft1@tigase.im/Hamza’s iPhone" type="unavailable"><c hash="sha-1" xmlns="http://jabber.org/protocol/caps" node="http://tigase.org/TigaseSwiftX" ver="+qMgYHw6R303EDP6b7J ... , SIZE=1086, XMLNS=tigase:cluster, PRIORITY=CLUSTER, PERMISSION=NONE, TYPE=set, STABLE_ID=null
[2021-04-22 20:56:06:987] [FINEST  ] [jabber:iq:register-proc-0 ] ClusterElement.<init>()       : Parsing cluster element: <cluster id="cl-6640997" xmlns="tigase:cluster" from="sess-man@ip-172-31-38-91.us-west-2.compute.internal" to="sess-man@ip-172-31-0-99.us-west-2.compute.internal" type="set" pr="CLUSTER"><control><visited-nodes><node-id>sess-man@ip-172-31-38-91.us-west-2.compute.internal</node-id></visited-nodes><method-call name="sess-man-user-disconnected-sm-cmd"><par name="userId">busoft1@tigase.im</par><par name="resource">Hamza’s iPhone</par><par name="connId">c2s@ip-172-31-38-91.us-west-2.compute.internal/172.19.0.2_5222_46.221.117.18_3024</par><par name="xmppSessId">b85b83d4-6ed1-4d25-b236-b8f32919d876</par><par name="auth-time">2081</par><par name="creation-t">1619124957887</par><par name="login_t">2081</par></method-call><first-node>sess-man@ip-172-31-38-91.us-west-2.compute.internal</first-node></control><data><presence xmlns="jabber:client" from="busoft1@tigase.im/Hamza’s iPhone" type="unavailable"><c hash="sha-1" xmlns="http://jabber.org/protocol/caps" node="http://tigase.org/TigaseSwiftX" ver="+qMgYHw6R303EDP6b7JlUN1I0HA="/><priority>5</priority></presence></data></cluster>
[2021-04-22 20:56:06:987] [FINEST  ] [jabber:iq:register-proc-0 ] ClusterElement.<init>()       : First node found: sess-man@ip-172-31-38-91.us-west-2.compute.internal
[2021-04-22 20:56:06:987] [FINEST  ] [jabber:iq:register-proc-0 ] ClusterElement.<init>()       : Found and added visited nodes: 1
[2021-04-22 20:56:06:987] [FINEST  ] [jabber:iq:register-proc-0 ] ConnectionManager.writePacketToSocket(): Writing packet: from=null, to=null, DATA=<cluster id="cl-6640997" xmlns="tigase:cluster" from="sess-man@ip-172-31-38-91.us-west-2.compute.internal" to="sess-man@ip-172-31-0-99.us-west-2.compute.internal" type="set" pr="CLUSTER"><control><visited-nodes><node-id>sess-man@ip-172-31-38-91.us-west-2.compute.internal</node-id></visited-nodes><method-call name="sess-man-user-disconnected-sm-cmd"><par name="userId">busoft1@tigase.im</par><par name="resource">Hamza’s iPhone</par><par name="connId">c2s@ip-172-31-38-91.us-west-2.compute.internal/172.19.0.2_5222_46.221.117.18_3024</par><par name="xmppSessId">b85b83d4-6ed1-4d25-b236-b8f32919d876</par><par name="auth-time">2081</par><par name="creation-t">1619124957887</par><par name="login_t">2081</par></method-call><first-node>sess-man@ip-172-31-38-91.us-west-2.compute.internal</first-node></control><data><presence xmlns="jabber:client" from="busoft1@tigase.im/Hamza’s iPhone" type="unavailable"><c hash="sha-1" xmlns="http://jabber.org/protocol/caps" node="http://tigase.org/TigaseSwiftX" ver="+qMgYHw6R303EDP6b7J ... , SIZE=1086, XMLNS=tigase:cluster, PRIORITY=CLUSTER, PERMISSION=NONE, TYPE=set, STABLE_ID=null [jid: ip-172-31-0-99.us-west-2.compute.internal, XMPPIOService, UniqueId: 172.19.0.2_44136_172.31.0.99_5277, type: -> outgoing (connect), SocketIO, ID: null, connected Socket[addr=ip-172-31-0-99.us-west-2.compute.internal/172.31.0.99,port=5277,localport=44136]]
[2021-04-22 20:56:06:987] [FINEST  ] [jabber:iq:register-proc-0 ] XMPPIOService.addPacketToSend(): Added packet to send: from=null, to=null, DATA=<cluster id="cl-6640997" xmlns="tigase:cluster" from="sess-man@ip-172-31-38-91.us-west-2.compute.internal" to="sess-man@ip-172-31-0-99.us-west-2.compute.internal" type="set" pr="CLUSTER"><control><visited-nodes><node-id>sess-man@ip-172-31-38-91.us-west-2.compute.internal</node-id></visited-nodes><method-call name="sess-man-user-disconnected-sm-cmd"><par name="userId">busoft1@tigase.im</par><par name="resource">Hamza’s iPhone</par><par name="connId">c2s@ip-172-31-38-91.us-west-2.compute.internal/172.19.0.2_5222_46.221.117.18_3024</par><par name="xmppSessId">b85b83d4-6ed1-4d25-b236-b8f32919d876</par><par name="auth-time">2081</par><par name="creation-t">1619124957887</par><par name="login_t">2081</par></method-call><first-node>sess-man@ip-172-31-38-91.us-west-2.compute.internal</first-node></control><data><presence xmlns="jabber:client" from="busoft1@tigase.im/Hamza’s iPhone" type="unavailable"><c hash="sha-1" xmlns="http://jabber.org/protocol/caps" node="http://tigase.org/TigaseSwiftX" ver="+qMgYHw6R303EDP6b7J ... , SIZE=1086, XMLNS=tigase:cluster, PRIORITY=CLUSTER, PERMISSION=NONE, TYPE=set, STABLE_ID=null [jid: ip-172-31-0-99.us-west-2.compute.internal, XMPPIOService, UniqueId: 172.19.0.2_44136_172.31.0.99_5277, type: -> outgoing (connect), SocketIO, ID: null, connected Socket[addr=ip-172-31-0-99.us-west-2.compute.internal/172.31.0.99,port=5277,localport=44136]]
[2021-04-22 20:56:06:988] [FINEST  ] [jabber:iq:register-proc-0 ] XMPPIOService.processWaitingPackets(): Sending packet: from=null, to=null, DATA=<cluster id="cl-6640997" xmlns="tigase:cluster" from="sess-man@ip-172-31-38-91.us-west-2.compute.internal" to="sess-man@ip-172-31-0-99.us-west-2.compute.internal" type="set" pr="CLUSTER"><control><visited-nodes><node-id>sess-man@ip-172-31-38-91.us-west-2.compute.internal</node-id></visited-nodes><method-call name="sess-man-user-disconnected-sm-cmd"><par name="userId">busoft1@tigase.im</par><par name="resource">Hamza’s iPhone</par><par name="connId">c2s@ip-172-31-38-91.us-west-2.compute.internal/172.19.0.2_5222_46.221.117.18_3024</par><par name="xmppSessId">b85b83d4-6ed1-4d25-b236-b8f32919d876</par><par name="auth-time">2081</par><par name="creation-t">1619124957887</par><par name="login_t">2081</par></method-call><first-node>sess-man@ip-172-31-38-91.us-west-2.compute.internal</first-node></control><data><presence xmlns="jabber:client" from="busoft1@tigase.im/Hamza’s iPhone" type="unavailable"><c hash="sha-1" xmlns="http://jabber.org/protocol/caps" node="http://tigase.org/TigaseSwiftX" ver="+qMgYHw6R303EDP6b7J ... , SIZE=1086, XMLNS=tigase:cluster, PRIORITY=CLUSTER, PERMISSION=NONE, TYPE=set, STABLE_ID=null [jid: ip-172-31-0-99.us-west-2.compute.internal, XMPPIOService, UniqueId: 172.19.0.2_44136_172.31.0.99_5277, type: -> outgoing (connect), SocketIO, ID: null, connected Socket[addr=ip-172-31-0-99.us-west-2.compute.internal/172.31.0.99,port=5277,localport=44136]]
[2021-04-22 20:56:06:988] [FINEST  ] [jabber:iq:register-proc-0 ] IOService.writeData()         : Writing data: 1,086 [SocketIO, ID: null, connected Socket[addr=ip-172-31-0-99.us-west-2.compute.internal/172.31.0.99,port=5277,localport=44136]]
[2021-04-22 20:56:06:988] [FINER   ] [jabber:iq:register-proc-0 ] SocketIO.write()              : SOCKET - Writing data, remaining: 1,090 [SocketIO, ID: null, connected Socket[addr=ip-172-31-0-99.us-west-2.compute.internal/172.31.0.99,port=5277,localport=44136]]
[2021-04-22 20:56:06:988] [FINER   ] [jabber:iq:register-proc-0 ] SocketIO.write()              : Wrote to channel 1,090 bytes [SocketIO, ID: null, connected Socket[addr=ip-172-31-0-99.us-west-2.compute.internal/172.31.0.99,port=5277,localport=44136]]
[2021-04-22 20:56:06:988] [FINEST  ] [jabber:iq:register-proc-0 ] IOService.writeData()         : Wrote: 1,086 [SocketIO, ID: null, connected Socket[addr=ip-172-31-0-99.us-west-2.compute.internal/172.31.0.99,port=5277,localport=44136]]
[2021-04-22 20:56:06:989] [FINEST  ] [jabber:iq:register-proc-0 ] XMPPIOService.processWaitingPackets(): SENT: <cluster id="cl-6640997" xmlns="tigase:cluster" from="sess-man@ip-172-31-38-91.us-west-2.compute.internal" to="sess-man@ip-172-31-0-99.us-west-2.compute.internal" type="set" pr="CLUSTER"><control><visited-nodes><node-id>sess-man@ip-172-31-38-91.us-west-2.compute.internal</node-id></visited-nodes><method-call name="sess-man-user-disconnected-sm-cmd"><par name="userId">busoft1@tigase.im</par><par name="resource">Hamza’s iPhone</par><par name="connId">c2s@ip-172-31-38-91.us-west-2.compute.internal/172.19.0.2_5222_46.221.117.18_3024</par><par name="xmppSessId">b85b83d4-6ed1-4d25-b236-b8f32919d876</par><par name="auth-time">2081</par><par name="creation-t">1619124957887</par><par name="login_t">2081</par></method-call><first-node>sess-man@ip-172-31-38-91.us-west-2.compute.internal</first-node></control><data><presence xmlns="jabber:client" from="busoft1@tigase.im/Hamza’s iPhone" type="unavailable"><c hash="sha-1" xmlns="http://jabber.org/protocol/caps" node="http://tigase.org/TigaseSwiftX" ver="+qMgYHw6R303EDP6b7JlUN1I0HA="/><priority>5</priority></presence></data></cluster> [jid: ip-172-31-0-99.us-west-2.compute.internal, XMPPIOService, UniqueId: 172.19.0.2_44136_172.31.0.99_5277, type: -> outgoing (connect), SocketIO, ID: null, connected Socket[addr=ip-172-31-0-99.us-west-2.compute.internal/172.31.0.99,port=5277,localport=44136]]
[2021-04-22 20:56:06:989] [FINEST  ] [jabber:iq:register-proc-0 ] SocketThread.addSocketServicePriv(): Adding to waiting: jid: ip-172-31-0-99.us-west-2.compute.internal, XMPPIOService, UniqueId: 172.19.0.2_44136_172.31.0.99_5277, type: -> outgoing (connect), SocketIO, ID: null, connected Socket[addr=ip-172-31-0-99.us-west-2.compute.internal/172.31.0.99,port=5277,localport=44136]
[2021-04-22 20:56:06:989] [FINEST  ] [jabber:iq:register-proc-0 ] SocketThread.run()            : Selector AWAKE: sun.nio.ch.EPollSelectorImpl@625dce76
[2021-04-22 20:56:06:989] [FINEST  ] [jabber:iq:register-proc-0 ] SocketThread.addAllWaiting()  : waiting.size(): 1
[2021-04-22 20:56:06:989] [FINEST  ] [jabber:iq:register-proc-0 ] SocketThread.addAllWaiting()  : ADDED OP_READ: SocketIO, ID: null, connected Socket[addr=ip-172-31-0-99.us-west-2.compute.internal/172.31.0.99,port=5277,localport=44136]
[2021-04-22 20:56:06:989] [FINEST  ] [jabber:iq:register-proc-0 ] ClusterConnectionManager.processPacket(): Processing packet: from=null, to=null, DATA=<cluster id="cl-6640998" xmlns="tigase:cluster" from="sess-man@ip-172-31-38-91.us-west-2.compute.internal" to="sess-man@ip-172-31-20-109.us-west-2.compute.internal" type="set" pr="CLUSTER"><control><visited-nodes><node-id>sess-man@ip-172-31-38-91.us-west-2.compute.internal</node-id></visited-nodes><method-call name="sess-man-user-disconnected-sm-cmd"><par name="userId">busoft1@tigase.im</par><par name="resource">Hamza’s iPhone</par><par name="connId">c2s@ip-172-31-38-91.us-west-2.compute.internal/172.19.0.2_5222_46.221.117.18_3024</par><par name="xmppSessId">b85b83d4-6ed1-4d25-b236-b8f32919d876</par><par name="auth-time">2081</par><par name="creation-t">1619124957887</par><par name="login_t">2081</par></method-call><first-node>sess-man@ip-172-31-38-91.us-west-2.compute.internal</first-node></control><data><presence xmlns="jabber:client" from="busoft1@tigase.im/Hamza’s iPhone" type="unavailable"><c hash="sha-1" xmlns="http://jabber.org/protocol/caps" node="http://tigase.org/TigaseSwiftX" ver="+qMgYHw6R303EDP6b ... , SIZE=1088, XMLNS=tigase:cluster, PRIORITY=CLUSTER, PERMISSION=NONE, TYPE=set, STABLE_ID=null
[2021-04-22 20:56:06:989] [FINEST  ] [jabber:iq:register-proc-0 ] ClusterElement.<init>()       : Parsing cluster element: <cluster id="cl-6640998" xmlns="tigase:cluster" from="sess-man@ip-172-31-38-91.us-west-2.compute.internal" to="sess-man@ip-172-31-20-109.us-west-2.compute.internal" type="set" pr="CLUSTER"><control><visited-nodes><node-id>sess-man@ip-172-31-38-91.us-west-2.compute.internal</node-id></visited-nodes><method-call name="sess-man-user-disconnected-sm-cmd"><par name="userId">busoft1@tigase.im</par><par name="resource">Hamza’s iPhone</par><par name="connId">c2s@ip-172-31-38-91.us-west-2.compute.internal/172.19.0.2_5222_46.221.117.18_3024</par><par name="xmppSessId">b85b83d4-6ed1-4d25-b236-b8f32919d876</par><par name="auth-time">2081</par><par name="creation-t">1619124957887</par><par name="login_t">2081</par></method-call><first-node>sess-man@ip-172-31-38-91.us-west-2.compute.internal</first-node></control><data><presence xmlns="jabber:client" from="busoft1@tigase.im/Hamza’s iPhone" type="unavailable"><c hash="sha-1" xmlns="http://jabber.org/protocol/caps" node="http://tigase.org/TigaseSwiftX" ver="+qMgYHw6R303EDP6b7JlUN1I0HA="/><priority>5</priority></presence></data></cluster>
[2021-04-22 20:56:06:990] [FINEST  ] [jabber:iq:register-proc-0 ] ClusterElement.<init>()       : First node found: sess-man@ip-172-31-38-91.us-west-2.compute.internal
[2021-04-22 20:56:06:990] [FINEST  ] [jabber:iq:register-proc-0 ] ClusterElement.<init>()       : Found and added visited nodes: 1
[2021-04-22 20:56:06:990] [FINEST  ] [jabber:iq:register-proc-0 ] ConnectionManager.writePacketToSocket(): Writing packet: from=null, to=null, DATA=<cluster id="cl-6640998" xmlns="tigase:cluster" from="sess-man@ip-172-31-38-91.us-west-2.compute.internal" to="sess-man@ip-172-31-20-109.us-west-2.compute.internal" type="set" pr="CLUSTER"><control><visited-nodes><node-id>sess-man@ip-172-31-38-91.us-west-2.compute.internal</node-id></visited-nodes><method-call name="sess-man-user-disconnected-sm-cmd"><par name="userId">busoft1@tigase.im</par><par name="resource">Hamza’s iPhone</par><par name="connId">c2s@ip-172-31-38-91.us-west-2.compute.internal/172.19.0.2_5222_46.221.117.18_3024</par><par name="xmppSessId">b85b83d4-6ed1-4d25-b236-b8f32919d876</par><par name="auth-time">2081</par><par name="creation-t">1619124957887</par><par name="login_t">2081</par></method-call><first-node>sess-man@ip-172-31-38-91.us-west-2.compute.internal</first-node></control><data><presence xmlns="jabber:client" from="busoft1@tigase.im/Hamza’s iPhone" type="unavailable"><c hash="sha-1" xmlns="http://jabber.org/protocol/caps" node="http://tigase.org/TigaseSwiftX" ver="+qMgYHw6R303EDP6b ... , SIZE=1088, XMLNS=tigase:cluster, PRIORITY=CLUSTER, PERMISSION=NONE, TYPE=set, STABLE_ID=null [jid: ip-172-31-20-109.us-west-2.compute.internal, XMPPIOService, UniqueId: 172.19.0.2_5277_172.31.20.109_35490, type: <- incoming (accept), SocketIO, ID: null, connected Socket[addr=/172.31.20.109,port=35490,localport=5277]]
[2021-04-22 20:56:06:990] [FINEST  ] [jabber:iq:register-proc-0 ] XMPPIOService.addPacketToSend(): Added packet to send: from=null, to=null, DATA=<cluster id="cl-6640998" xmlns="tigase:cluster" from="sess-man@ip-172-31-38-91.us-west-2.compute.internal" to="sess-man@ip-172-31-20-109.us-west-2.compute.internal" type="set" pr="CLUSTER"><control><visited-nodes><node-id>sess-man@ip-172-31-38-91.us-west-2.compute.internal</node-id></visited-nodes><method-call name="sess-man-user-disconnected-sm-cmd"><par name="userId">busoft1@tigase.im</par><par name="resource">Hamza’s iPhone</par><par name="connId">c2s@ip-172-31-38-91.us-west-2.compute.internal/172.19.0.2_5222_46.221.117.18_3024</par><par name="xmppSessId">b85b83d4-6ed1-4d25-b236-b8f32919d876</par><par name="auth-time">2081</par><par name="creation-t">1619124957887</par><par name="login_t">2081</par></method-call><first-node>sess-man@ip-172-31-38-91.us-west-2.compute.internal</first-node></control><data><presence xmlns="jabber:client" from="busoft1@tigase.im/Hamza’s iPhone" type="unavailable"><c hash="sha-1" xmlns="http://jabber.org/protocol/caps" node="http://tigase.org/TigaseSwiftX" ver="+qMgYHw6R303EDP6b ... , SIZE=1088, XMLNS=tigase:cluster, PRIORITY=CLUSTER, PERMISSION=NONE, TYPE=set, STABLE_ID=null [jid: ip-172-31-20-109.us-west-2.compute.internal, XMPPIOService, UniqueId: 172.19.0.2_5277_172.31.20.109_35490, type: <- incoming (accept), SocketIO, ID: null, connected Socket[addr=/172.31.20.109,port=35490,localport=5277]]
[2021-04-22 20:56:06:990] [FINEST  ] [jabber:iq:register-proc-0 ] XMPPIOService.processWaitingPackets(): Sending packet: from=null, to=null, DATA=<cluster id="cl-6640998" xmlns="tigase:cluster" from="sess-man@ip-172-31-38-91.us-west-2.compute.internal" to="sess-man@ip-172-31-20-109.us-west-2.compute.internal" type="set" pr="CLUSTER"><control><visited-nodes><node-id>sess-man@ip-172-31-38-91.us-west-2.compute.internal</node-id></visited-nodes><method-call name="sess-man-user-disconnected-sm-cmd"><par name="userId">busoft1@tigase.im</par><par name="resource">Hamza’s iPhone</par><par name="connId">c2s@ip-172-31-38-91.us-west-2.compute.internal/172.19.0.2_5222_46.221.117.18_3024</par><par name="xmppSessId">b85b83d4-6ed1-4d25-b236-b8f32919d876</par><par name="auth-time">2081</par><par name="creation-t">1619124957887</par><par name="login_t">2081</par></method-call><first-node>sess-man@ip-172-31-38-91.us-west-2.compute.internal</first-node></control><data><presence xmlns="jabber:client" from="busoft1@tigase.im/Hamza’s iPhone" type="unavailable"><c hash="sha-1" xmlns="http://jabber.org/protocol/caps" node="http://tigase.org/TigaseSwiftX" ver="+qMgYHw6R303EDP6b ... , SIZE=1088, XMLNS=tigase:cluster, PRIORITY=CLUSTER, PERMISSION=NONE, TYPE=set, STABLE_ID=null [jid: ip-172-31-20-109.us-west-2.compute.internal, XMPPIOService, UniqueId: 172.19.0.2_5277_172.31.20.109_35490, type: <- incoming (accept), SocketIO, ID: null, connected Socket[addr=/172.31.20.109,port=35490,localport=5277]]
[2021-04-22 20:56:06:991] [FINEST  ] [jabber:iq:register-proc-0 ] IOService.writeData()         : Writing data: 1,088 [SocketIO, ID: null, connected Socket[addr=/172.31.20.109,port=35490,localport=5277]]
[2021-04-22 20:56:06:991] [FINER   ] [jabber:iq:register-proc-0 ] SocketIO.write()              : SOCKET - Writing data, remaining: 1,092 [SocketIO, ID: null, connected Socket[addr=/172.31.20.109,port=35490,localport=5277]]
[2021-04-22 20:56:06:991] [FINER   ] [jabber:iq:register-proc-0 ] SocketIO.write()              : Wrote to channel 1,092 bytes [SocketIO, ID: null, connected Socket[addr=/172.31.20.109,port=35490,localport=5277]]
[2021-04-22 20:56:06:991] [FINEST  ] [jabber:iq:register-proc-0 ] IOService.writeData()         : Wrote: 1,088 [SocketIO, ID: null, connected Socket[addr=/172.31.20.109,port=35490,localport=5277]]
[2021-04-22 20:56:06:991] [FINEST  ] [jabber:iq:register-proc-0 ] XMPPIOService.processWaitingPackets(): SENT: <cluster id="cl-6640998" xmlns="tigase:cluster" from="sess-man@ip-172-31-38-91.us-west-2.compute.internal" to="sess-man@ip-172-31-20-109.us-west-2.compute.internal" type="set" pr="CLUSTER"><control><visited-nodes><node-id>sess-man@ip-172-31-38-91.us-west-2.compute.internal</node-id></visited-nodes><method-call name="sess-man-user-disconnected-sm-cmd"><par name="userId">busoft1@tigase.im</par><par name="resource">Hamza’s iPhone</par><par name="connId">c2s@ip-172-31-38-91.us-west-2.compute.internal/172.19.0.2_5222_46.221.117.18_3024</par><par name="xmppSessId">b85b83d4-6ed1-4d25-b236-b8f32919d876</par><par name="auth-time">2081</par><par name="creation-t">1619124957887</par><par name="login_t">2081</par></method-call><first-node>sess-man@ip-172-31-38-91.us-west-2.compute.internal</first-node></control><data><presence xmlns="jabber:client" from="busoft1@tigase.im/Hamza’s iPhone" type="unavailable"><c hash="sha-1" xmlns="http://jabber.org/protocol/caps" node="http://tigase.org/TigaseSwiftX" ver="+qMgYHw6R303EDP6b7JlUN1I0HA="/><priority>5</priority></presence></data></cluster> [jid: ip-172-31-20-109.us-west-2.compute.internal, XMPPIOService, UniqueId: 172.19.0.2_5277_172.31.20.109_35490, type: <- incoming (accept), SocketIO, ID: null, connected Socket[addr=/172.31.20.109,port=35490,localport=5277]]
[2021-04-22 20:56:06:991] [FINEST  ] [jabber:iq:register-proc-0 ] SocketThread.addSocketServicePriv(): Adding to waiting: jid: ip-172-31-20-109.us-west-2.compute.internal, XMPPIOService, UniqueId: 172.19.0.2_5277_172.31.20.109_35490, type: <- incoming (accept), SocketIO, ID: null, connected Socket[addr=/172.31.20.109,port=35490,localport=5277]
[2021-04-22 20:56:06:990] [FINEST  ] [jabber:iq:register-proc-0 ] RepositoryAccess.setData()    : Problem accessing reposiotry: 
tigase.db.UserNotFoundException: User does not exist: busoft1@tigase.im
	at tigase.db.jdbc.JDBCRepository.getUserUID(JDBCRepository.java:1195)
	at tigase.db.jdbc.JDBCRepository.setData(JDBCRepository.java:650)
	at jdk.internal.reflect.GeneratedMethodAccessor103.invoke(Unknown Source)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
	at java.base/java.lang.reflect.Method.invoke(Unknown Source)
	at tigase.stats.StatisticsInvocationHandler.invoke(StatisticsInvocationHandler.java:75)
	at com.sun.proxy.$Proxy44.setData(Unknown Source)
	at tigase.db.UserRepositoryMDImpl.setData(UserRepositoryMDImpl.java:341)
	at tigase.xmpp.RepositoryAccess.setData(RepositoryAccess.java:470)
	at tigase.xmpp.impl.roster.RosterFlat.saveUserRoster(RosterFlat.java:597)
	at tigase.xmpp.impl.roster.RosterFlat.logout(RosterFlat.java:524)
	at tigase.xmpp.impl.PresenceState.stopped(PresenceState.java:471)
	at tigase.server.xmppsession.SessionManager.closeSession(SessionManager.java:967)
	at tigase.cluster.SessionManagerClustered.closeSession(SessionManagerClustered.java:491)
	at tigase.server.xmppsession.SessionManager.handleLogout(SessionManager.java:355)
	at tigase.cluster.SessionManagerClustered.handleLogout(SessionManagerClustered.java:173)
	at tigase.xmpp.XMPPResourceConnection.logout(XMPPResourceConnection.java:191)
	at tigase.xmpp.impl.JabberIqRegister.doRemoveAccount(JabberIqRegister.java:540)
	at tigase.xmpp.impl.JabberIqRegister.process(JabberIqRegister.java:336)
	at tigase.server.xmppsession.SessionManager$ProcessorWorkerThread.process(SessionManager.java:2656)
	at tigase.util.processing.WorkerThread.run(WorkerThread.java:67)

[2021-04-22 20:56:06:992] [WARNING ] [jabber:iq:register-proc-0 ] RosterFlat.logout()           : Error logging out user
tigase.xmpp.NotAuthorizedException: Can not access user repository.
	at tigase.xmpp.RepositoryAccess.setData(RepositoryAccess.java:474)
	at tigase.xmpp.impl.roster.RosterFlat.saveUserRoster(RosterFlat.java:597)
	at tigase.xmpp.impl.roster.RosterFlat.logout(RosterFlat.java:524)
	at tigase.xmpp.impl.PresenceState.stopped(PresenceState.java:471)
	at tigase.server.xmppsession.SessionManager.closeSession(SessionManager.java:967)
	at tigase.cluster.SessionManagerClustered.closeSession(SessionManagerClustered.java:491)
	at tigase.server.xmppsession.SessionManager.handleLogout(SessionManager.java:355)
	at tigase.cluster.SessionManagerClustered.handleLogout(SessionManagerClustered.java:173)
	at tigase.xmpp.XMPPResourceConnection.logout(XMPPResourceConnection.java:191)
	at tigase.xmpp.impl.JabberIqRegister.doRemoveAccount(JabberIqRegister.java:540)
	at tigase.xmpp.impl.JabberIqRegister.process(JabberIqRegister.java:336)
	at tigase.server.xmppsession.SessionManager$ProcessorWorkerThread.process(SessionManager.java:2656)
	at tigase.util.processing.WorkerThread.run(WorkerThread.java:67)
Caused by: tigase.db.UserNotFoundException: User does not exist: busoft1@tigase.im
	at tigase.db.jdbc.JDBCRepository.getUserUID(JDBCRepository.java:1195)
	at tigase.db.jdbc.JDBCRepository.setData(JDBCRepository.java:650)
	at jdk.internal.reflect.GeneratedMethodAccessor103.invoke(Unknown Source)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
	at java.base/java.lang.reflect.Method.invoke(Unknown Source)
	at tigase.stats.StatisticsInvocationHandler.invoke(StatisticsInvocationHandler.java:75)
	at com.sun.proxy.$Proxy44.setData(Unknown Source)
	at tigase.db.UserRepositoryMDImpl.setData(UserRepositoryMDImpl.java:341)
	at tigase.xmpp.RepositoryAccess.setData(RepositoryAccess.java:470)
	... 12 more

Andrzej Wójcik (Tigase) commented 4 years ago

I've fixed the issue by reducing log level to FINEST if exception NotAuthorizedException is caused by tigase.db.UserNotFoundException at RosterFlat.logout
Login to comment

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

Issue Votes (0)

Watchers (0)

Reference

tigase/_server/server-core#1250