Tigase Forge
Dashboards
Projects
Pull Requests
Issues
Builds
Packages
Code Search
tigase-muc
Code
Pull Requests
Issues
List
Boards
Iterations
Builds
Statistics
Child Projects
OneDev 10.9.4
Documentation Support & Bug Report RESTful API Incompatibilities License Agreement Check Update
Projects tigase _server tigase-muc Issues #138
tigase@muc.tigase.org kicks my clients if I use them both (#138)
Closed
wojciech.kapcia@tigase.net opened 4 years ago

https://github.com/tigase/tigase-server/issues/63

With the CloudWatch and detailed logs I noticed this:

2021-02-22 16:20:38.019 TRACE [ in_0-muc] t.c.m.StanzaProcessor.processPacket(): XMPP error condition: not-acceptable with message: "dino.f227906b is not in room" generated by tigase.muc.modules.IqStanzaForwarderModule.lambda$process$1(IqStanzaForwarderModule.java:120) when processing from=s2s@ip-172-31-2-168.us-west-2.compute.internal, to=null, DATA=<iq type="get" xml:lang="en" xmlns="jabber:client" from="…@…/dino.f227906b" id="13d1bf75-8756-4a03-9d2e-292ec75d0433" to="tigase@muc.tigase.org/…"><ping xmlns="urn:xmpp:ping"/></iq>, SIZE=203, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=REMOTE, TYPE=get, STABLE_ID=null
tigase.muc.exceptions.MUCException: XMPP error condition: not-acceptable with message: "dino.f227906b is not in room"
at tigase.muc.modules.IqStanzaForwarderModule.lambda$process$1(IqStanzaForwarderModule.java:120)
at java.base/java.util.Optional.orElseThrow(Unknown Source)
at tigase.muc.modules.IqStanzaForwarderModule.process(IqStanzaForwarderModule.java:119)
at tigase.component.modules.StanzaProcessor.process(StanzaProcessor.java:164)
at tigase.component.modules.StanzaProcessor.processPacket(StanzaProcessor.java:85)
at tigase.component.AbstractKernelBasedComponent.processPacket(AbstractKernelBasedComponent.java:81)
at tigase.muc.MUCComponent.processPacket(MUCComponent.java:122)
at tigase.muc.cluster.MUCComponentClustered.processPacket(SourceFile:87)
at tigase.server.AbstractMessageReceiver$QueueListener.run(AbstractMessageReceiver.java:1397)

Those exceptions are logged with FINE* level so normally they don't generate notifications but most likely are related to the issue with dino.
wojciech.kapcia@tigase.net commented 3 years ago

I had to add more debugging but with that in place I got:

[2021-09-29 21:03:15:968] [FINEST  ] [             in_21-muc ] SelfPingModule.process()         : Processing ping packet: from=sess-man@localhost, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<iq from="admin@atlantiscity/converse.js-20985360" type="get" xmlns="jabber:client" to="myroom@muc.atlantiscity/admin" id="cedae47b-702f-4cf5-9d5f-cbd3fdff3b29:sendIQ"><ping xmlns="urn:xmpp:ping"/></iq>, SIZE=202, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=ADMIN, TYPE=get, STABLE_ID=null, module-ping: false, room-ping: false
[2021-09-29 21:03:15:968] [FINEST  ] [             in_21-muc ] SelfPingModule.process()         : Processing ping packet[2]: from=sess-man@localhost, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<iq from="admin@atlantiscity/converse.js-20985360" type="get" xmlns="jabber:client" to="myroom@muc.atlantiscity/admin" id="cedae47b-702f-4cf5-9d5f-cbd3fdff3b29:sendIQ"><ping xmlns="urn:xmpp:ping"/></iq>, SIZE=202, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=ADMIN, TYPE=get, STABLE_ID=null, recipientJids: [admin@atlantiscity/1204607085-tigase-2, admin@atlantiscity/converse.js-20985360], room: tigase.muc.RoomWithId@11b8a4c6
[2021-09-29 21:03:15:968] [FINEST  ] [             in_21-muc ] SelfPingerMonitor.register()     : PRegistering for ping, from: admin@atlantiscity/converse.js-20985360, to: myroom@muc.atlantiscity/admin, id: cedae47b-702f-4cf5-9d5f-cbd3fdff3b29:sendIQ, requests: 3
[2021-09-29 21:03:15:969] [FINEST  ] [             in_21-muc ] SelfPingModule.pingAll()         : Pinging connections, stanzaId: cedae47b-702f-4cf5-9d5f-cbd3fdff3b29:sendIQ, from: admin@atlantiscity/converse.js-20985360, to: myroom@muc.atlantiscity/admin, recipientJids: [admin@atlantiscity/1204607085-tigase-2, admin@atlantiscity/converse.js-20985360], request: Request{id='cedae47b-702f-4cf5-9d5f-cbd3fdff3b29:sendIQ', jid=admin@atlantiscity/converse.js-20985360, jidTo=myroom@muc.atlantiscity/admin, timestampt=1632942195968, requestsCounter=0, resultErrorCounter=0, resultOkCounter=0, resultTimeoutCounter=0, timeoutedJIDs=[]}
[2021-09-29 21:03:15:969] [FINER   ] [             in_21-muc ] AbstractKernelBasedComponent$DefaultPacketWriter.write(): Sent: from=null, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<iq xmlns="jabber:client" to="admin@atlantiscity/1204607085-tigase-2" id="spng-9" from="myroom@muc.atlantiscity/admin" type="get"><ping xmlns="urn:xmpp:ping"/></iq>, SIZE=164, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=get, STABLE_ID=null
[2021-09-29 21:03:15:969] [FINER   ] [             in_21-muc ] AbstractKernelBasedComponent$DefaultPacketWriter.write(): Sent: from=null, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<iq xmlns="jabber:client" to="admin@atlantiscity/converse.js-20985360" id="spng-10" from="myroom@muc.atlantiscity/admin" type="get"><ping xmlns="urn:xmpp:ping"/></iq>, SIZE=166, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=get, STABLE_ID=null
…
[2021-09-29 21:03:15:993] [FINEST  ] [             in_21-muc ] SelfPingerMonitor.registerResponse(): Registering response ping, jid: sess-man@localhost, stanzaId: spng-9, result: Ok, req: null
[2021-09-29 21:03:16:002] [FINEST  ] [             in_21-muc ] SelfPingerMonitor.registerResponse(): Registering response ping, jid: sess-man@localhost, stanzaId: spng-10, result: Ok, req: null
…
[2021-09-29 21:04:26:342] [FINEST  ] [  urn:xmpp:ping-proc-0 ] DomainFilter.getDomains()        : Domains read from user session: ALL for VHost: atlantiscity
[2021-09-29 21:04:35:477] [FINEST  ] [scheduler_pool-14-thread-1-muc ] SelfPingerMonitor.finish(): Finishing request: Request{id='cedae47b-702f-4cf5-9d5f-cbd3fdff3b29:sendIQ', jid=admin@atlantiscity/converse.js-20985360, jidTo=myroom@muc.atlantiscity/admin, timestampt=1632942195968, requestsCounter=2, resultErrorCounter=0, resultOkCounter=0, resultTimeoutCounter=0, timeoutedJIDs=[admin@atlantiscity/1204607085-tigase-2, admin@atlantiscity/converse.js-20985360]}
[2021-09-29 21:04:35:478] [FINEST  ] [scheduler_pool-14-thread-1-muc ] SelfPingModule.onPingMultirequestFinished(): Finished processing, req: Request{id='cedae47b-702f-4cf5-9d5f-cbd3fdff3b29:sendIQ', jid=admin@atlantiscity/converse.js-20985360, jidTo=myroom@muc.atlantiscity/admin, timestampt=1632942195968, requestsCounter=2, resultErrorCounter=0, resultOkCounter=0, resultTimeoutCounter=0, timeoutedJIDs=[admin@atlantiscity/1204607085-tigase-2, admin@atlantiscity/converse.js-20985360]}, result: Timeouts
[2021-09-29 21:04:35:478] [FINER   ] [scheduler_pool-14-thread-1-muc ] AbstractKernelBasedComponent$DefaultPacketWriter.write(): Sent: from=null, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<iq xmlns="jabber:client" to="admin@atlantiscity/converse.js-20985360" id="cedae47b-702f-4cf5-9d5f-cbd3fdff3b29:sendIQ" from="myroom@muc.atlantiscity/admin" type="error"><error type="cancel"><service-unavailable xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/></error></iq>, SIZE=270, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=error, STABLE_ID=null
[2021-09-29 21:04:35:478] [FINEST  ] [scheduler_pool-14-thread-1-muc ] SelfPingerMonitor.kickOut(): Kicking out JID: admin@atlantiscity/1204607085-tigase-2
[2021-09-29 21:04:35:478] [FINEST  ] [scheduler_pool-14-thread-1-muc ] Ghostbuster2.kickJIDFromRooms(): Kicking out JID: admin@atlantiscity/1204607085-tigase-2, from rooms: null
[2021-09-29 21:04:35:480] [FINEST  ] [       in_108-sess-man ] DomainFilter.filter()            : Filtering (packet): from=null, to=sess-man@localhost, serverAuthorisedStanzaFrom=Optional.empty, DATA=<iq xmlns="jabber:client" to="admin@atlantiscity/converse.js-20985360" id="cedae47b-702f-4cf5-9d5f-cbd3fdff3b29:sendIQ" from="myroom@muc.atlantiscity/admin" type="error"><error type="cancel"><service-unavailable xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/></error></iq>, SIZE=270, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=ADMIN, TYPE=error, STABLE_ID=5463d097-e71d-4a85-a820-d67f5e3abae1
…
[2021-09-29 21:04:35:481] [FINEST  ] [scheduler_pool-14-thread-1-muc ] PresenceStore.findPresence(): User resources presences: {converse.js-20985360=Presence[priority=0, type=null, show=null, from=admin@atlantiscity/converse.js-20985360, lastUpdated=Wed Sep 29 21:03:26 CEST 2021]}
[2021-09-29 21:04:35:481] [FINEST  ] [scheduler_pool-14-thread-1-muc ] PresenceStore.updateBestPresence(): Selected BestPresence: <presence from="admin@atlantiscity/converse.js-20985360" xmlns="jabber:client" to="myroom@muc.atlantiscity/admin"><c node="https://conversejs.org" xmlns="http://jabber.org/protocol/caps" hash="sha-1" ver="TfHz9vOOfqIG0Z9lW5CuPaWGnrQ="/></presence>
[2021-09-29 21:04:35:481] [FINEST  ] [scheduler_pool-14-thread-1-muc ] Room.updatePresenceByJid(): Room myroom@muc.atlantiscity. Removed presence from admin@atlantiscity/1204607085-tigase-2 (admin)
[2021-09-29 21:04:35:482] [FINEST  ] [scheduler_pool-14-thread-1-muc ] Room.getAffiliation()    : Getting affiliations for: admin@atlantiscity, result : [aff: owner,persistent: false,nickname: null]
[2021-09-29 21:04:35:482] [FINER   ] [scheduler_pool-14-thread-1-muc ] AbstractKernelBasedComponent$DefaultPacketWriter.write(): Sent: from=null, to=null, serverAuthorisedStanzaFrom=Optional.empty, DATA=<presence xmlns="jabber:client" to="admin@atlantiscity/1204607085-tigase-2" from="myroom@muc.atlantiscity/admin" type="unavailable"><x xmlns="http://jabber.org/protocol/muc#user"><item affiliation="owner" role="none" nick="admin" jid="admin@atlantiscity/1204607085-tigase-2"/><item affiliation="owner" role="none" nick="admin" jid="admin@atlantiscity/converse.js-20985360"/><status code="110"/><status code="333"/></x></presence>, SIZE=429, XMLNS=jabber:client, PRIORITY=HIGH, PERMISSION=NONE, TYPE=unavailable, STABLE_ID=null
[2021-09-29 21:04:35:482] [FINEST  ] [scheduler_pool-14-thread-1-muc ] Room.getRole()           : Getting role for nick: admin. OccupantEntry: [admin; moderator; admin@atlantiscity; [admin@atlantiscity/converse.js-20985360]]
[2021-09-29 21:04:35:482] [FINEST  ] [       in_108-sess-man ] JabberIqPrivacy.allowed()        : Using privacy list: PrivacyList[name=null, size: 0, items: ]
[2021-09-29 21:04:35:482] [FINEST  ] [scheduler_pool-14-thread-1-muc ] Room.getAffiliation()    : Getting affiliations for: admin@atlantiscity, result : [aff: owner,persistent: false,nickname: null]
…
[2021-09-29 21:04:35:483] [FINEST  ] [scheduler_pool-14-thread-1-muc ] SelfPingerMonitor.kickOut(): Kicking out JID: admin@atlantiscity/converse.js-20985360
[2021-09-29 21:04:35:483] [FINEST  ] [scheduler_pool-14-thread-1-muc ] Ghostbuster2.kickJIDFromRooms(): Kicking out JID: admin@atlantiscity/converse.js-20985360, from rooms: null

The most relevant bit is in the middle:

[2021-09-29 21:03:15:993] [FINEST  ] [             in_21-muc ] SelfPingerMonitor.registerResponse(): Registering response ping, jid: sess-man@localhost, stanzaId: spng-9, result: Ok, req: null
[2021-09-29 21:03:16:002] [FINEST  ] [             in_21-muc ] SelfPingerMonitor.registerResponse(): Registering response ping, jid: sess-man@localhost, stanzaId: spng-10, result: Ok, req: null

basically wrong from was used which made ghostbuster to virtually always fail. (separate issue is that it would most likely be failing in cluster…)
wojciech.kapcia@tigase.net commented 3 years ago
wojciech.kapcia@tigase.net commented 3 years ago

Half hour after de deployment I don't see any kicking out of the users...
issue 1 of 1
Type
Bug
Priority
Normal
Assignee
wojciech.kapcia@tigase.net
Version
tigase-server-8.2.0, tigase-server-8.1.3
Issue Votes (0)
Login to vote
Watchers (0)
Reference
tigase/_server/tigase-muc#138
Please wait...
Page is in error, reload to recover