Tigase Forge
Dashboards
Projects
Pull Requests
Issues
Builds
Packages
Code Search
server-core
Code
Pull Requests
Issues
List
Boards
Iterations
Builds
Packages
Statistics
Child Projects
OneDev 11.5.2
Documentation Support & Bug Report RESTful API Incompatibilities License Agreement Check Update
Projects tigase _server server-core Issues #1250
UserNotFoundException in SessionManagerClustered.handleLogout (#1250)
wojciech.kapcia@tigase.net 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:

  1. it looks like the account was removed on one node and then due to concurrency exception was thrown on another
  2. It seems, that at the least just changing log level should be enough as this doesn't seem essential to system operation.
wojciech.kapcia@tigase.net 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
issue 1 of 1
Type
Bug
Priority
Minor
Assignee
wojciech.kapcia@tigase.net
Version
tigase-server-8.2.0
Spent time
30m
Issue Votes (0)
Login to vote
Watchers (0)
Reference
tigase/_server/server-core#1250
Please wait...
Page is in error, reload to recover