Project

General

Profile

Incorrect disconnect behavior when using Resource in JID

Matt Morten
Added over 4 years ago

Hi,

When I log in using a JID + resource string, the disconnect behavior seems to be wrong. The server only sees the disconnection when I re-login with a new resource string:

1) Connect client 1 (resource: 905952889734669467)

2) Disconnect client 1

… I expect to see something in the logs here, but don't

3) Connect client 2 (resource: 2842255420944604475)

… receive disconnect notification for client 1 in the logs

However when I remove resource strings from conn.login(), everything works as expected.

I am using Smack to connect and log in to Tigase 5.2.1-b3461:

ConnectionConfiguration config = new ConnectionConfiguration("moomin2.local", 5222);
config.setCompressionEnabled(true);
conn = new XMPPConnection(config);

conn.connect();
resource = Math.abs(new Random().nextLong()) + "";

conn.login(app + '#' + name, password, resource);

Here is what I see in the logs when I connect client 2:

2014-07-16 12:13:17.296 [in_6-c2s]         ClientConnectionManager.xmppStreamClosed()  FINER: Stream closed: c2s@moomin2.local/192.168.140.134_5222_192.168.140.134_50369
2014-07-16 12:13:17.296 [in_6-c2s]         ClientConnectionManager.xmppStreamClosed()  FINE: Service stopped, sending packet: from=null, to=null, DATA=<iq from="c2s@moomin2.local/192.168.140.134_5222_192.168.140.134_50369" id="6db64186-bec4-4eb9-8822-d1e47d585f4b" to="sess-man@moomin2.local" type="set"><command xmlns="http://jabber.org/protocol/commands" node="STREAM_CLOSED"><x xmlns="jabber:x:data" type="submit"><field var="user-jid"><value>vdxmdgfcwbqdvhoudllahxwrwdyk5zut#alice@moomin2.local/905952889734669467</value></field></x></command></iq>, SIZE=401, XMLNS=null, PRIORITY=SYSTEM, PERMISSION=NONE, TYPE=set
2014-07-16 12:13:17.297 [in_23-message-router]  MessageRouter.processPacket()  FINEST:  Processing packet: from=null, to=null, DATA=<iq from="c2s@moomin2.local/192.168.140.134_5222_192.168.140.134_50369" id="6db64186-bec4-4eb9-8822-d1e47d585f4b" to="sess-man@moomin2.local" type="set"><command xmlns="http://jabber.org/protocol/commands" node="STREAM_CLOSED"><x xmlns="jabber:x:data" type="submit"><field var="user-jid"><value>vdxmdgfcwbqdvhoudllahxwrwdyk5zut#alice@moomin2.local/905952889734669467</value></field></x></command></iq>, SIZE=401, XMLNS=null, PRIORITY=SYSTEM, PERMISSION=NONE, TYPE=set
2014-07-16 12:13:17.297 [in_23-message-router]  MessageRouter.processPacket()  FINEST:  1. Packet will be processed by: sess-man@moomin2.local, from=null, to=null, DATA=<iq from="c2s@moomin2.local/192.168.140.134_5222_192.168.140.134_50369" id="6db64186-bec4-4eb9-8822-d1e47d585f4b" to="sess-man@moomin2.local" type="set"><command xmlns="http://jabber.org/protocol/commands" node="STREAM_CLOSED"><x xmlns="jabber:x:data" type="submit"><field var="user-jid"><value>vdxmdgfcwbqdvhoudllahxwrwdyk5zut#alice@moomin2.local/905952889734669467</value></field></x></command></iq>, SIZE=401, XMLNS=null, PRIORITY=SYSTEM, PERMISSION=NONE, TYPE=set
2014-07-16 12:13:17.297 [in_23-sess-man]   SessionManager.processCommand()    FINER:    STREAM_CLOSED command from: c2s@moomin2.local/192.168.140.134_5222_192.168.140.134_50369
2014-07-16 12:13:17.297 [session-close Queue Worker 3]  SessionManager$SessionCloseProc.process()  FINEST: Executing connection close for: from=null, to=null, DATA=<iq from="c2s@moomin2.local/192.168.140.134_5222_192.168.140.134_50369" id="6db64186-bec4-4eb9-8822-d1e47d585f4b" to="sess-man@moomin2.local" type="set"><command xmlns="http://jabber.org/protocol/commands" node="STREAM_CLOSED"><x xmlns="jabber:x:data" type="submit"><field var="user-jid"><value>vdxmdgfcwbqdvhoudllahxwrwdyk5zut#alice@moomin2.local/905952889734669467</value></field></x></command></iq>, SIZE=401, XMLNS=null, PRIORITY=SYSTEM, PERMISSION=NONE, TYPE=set
2014-07-16 12:13:17.298 [session-close Queue Worker 3]  SessionManager.closeConnection()  FINER: Stream closed from: c2s@moomin2.local/192.168.140.134_5222_192.168.140.134_50369
2014-07-16 12:13:17.299 [session-close Queue Worker 3]  SessionManager.closeSession()  FINE: Closing connection for: vdxmdgfcwbqdvhoudllahxwrwdyk5zut#alice@moomin2.local/905952889734669467
2014-07-16 12:13:17.299 [session-close Queue Worker 3]  SessionManager.closeSession()  FINE: Found parent session for: vdxmdgfcwbqdvhoudllahxwrwdyk5zut#alice@moomin2.local/905952889734669467
2014-07-16 12:13:17.299 [session-close Queue Worker 3]  SessionManager.closeSession()  FINER: Number of connections is 2 for the user: vdxmdgfcwbqdvhoudllahxwrwdyk5zut#alice@moomin2.local/905952889734669467, res=905952889734669467, res=2842255420944604475

Any help would be appreciated.


Replies (13)

Avatar?id=6023&size=32x32

Added by Artur Hefczyc TigaseTeam over 4 years ago

It is hard to tell anything specific with so little details. Most likely the operating system reports disconnection to application with a delay, so the Tigase server sees disconnection later. Have you tried to connect the user with a resource and disconnect it and wait to see when the server sees disconnection?

Also, how do you disconnect?

Added by Matt Morten over 4 years ago

I guess what confuses me is that, when I connect without the resource string, it works fine. I'm not sure this would be an OS thing… :-\

I am disconnecting by simply killing the JVM of my client.

When disconnecting client 1, I immediately see the following (--debug=server,net)

014-07-16 12:49:50.371 [socketReadThread-28]  SocketThread.run()             FINEST:   Selector AWAKE: sun.nio.ch.KQueueSelectorImpl@1809b02d
2014-07-16 12:49:50.371 [socketReadThread-28]  SocketThread.run()             FINEST:   AWAKEN: 192.168.140.134_5222_192.168.140.134_50989, ready for READING, readyOps() = 1
2014-07-16 12:49:50.371 [socketReadThread-28]  SocketThread.addAllWaiting()   FINEST:   waiting.size(): 0
2014-07-16 12:49:50.372 [pool-20-thread-12]  IOService.isConnected()          FINEST:   Socket: TLS: c2s@moomin2.local/192.168.140.134_5222_192.168.140.134_50989 Socket[addr=/192.168.140.134,port=50989,localport=5222], Connected: true, id: c2s@moomin2.local/192.168.140.134_5222_192.168.140.134_50989
2014-07-16 12:49:50.372 [pool-20-thread-12]  IOUtil$BufferCache.get()         FINEST:   allocating buffer with size = 132,704
2014-07-16 12:49:50.373 [pool-20-thread-12]  IOService.isConnected()          FINEST:   Socket: TLS: c2s@moomin2.local/192.168.140.134_5222_192.168.140.134_50989 Socket[unconnected], Connected: false, id: c2s@moomin2.local/192.168.140.134_5222_192.168.140.134_50989
2014-07-16 12:49:50.373 [ResultsListener-socketWriteThread-20]  IOService.isConnected()  FINEST: Socket: TLS: c2s@moomin2.local/192.168.140.134_5222_192.168.140.134_50989 Socket[unconnected], Connected: false, id: c2s@moomin2.local/192.168.140.134_5222_192.168.140.134_50989

.. but then nothing from ClientConnectionManager or SessionManager. I have waited a couple of hours but no more log messages. I connect client 2 and then I get the proper Disconnect notification.

Avatar?id=6023&size=32x32

Added by Artur Hefczyc TigaseTeam over 4 years ago

This is really strange, I have never seen a problem like this. We have to investigate it. I have created a ticket: #2072 and added you to watchers. Please monitor the progress of investigation and provide more information if requested.

Thank you for reporting the problem,

Added by Matt Morten over 4 years ago

Thank you. Let me know if you need any more information from me.

Added by Andrzej Wójcik IoT 1 CloudTigaseTeam over 4 years ago

This issue looks like similar or related to issue #1879 which might be already fixed in 5.3.0-SNAPSHOT due to implementation of #1933

Added by Matt Morten over 4 years ago

Stupid question - can I upgrade my install to 5.3.0-SNAPSHOT simply by replacing jars/tigase-server.jar? Or is it more involved?

Avatar?id=6023&size=32x32

Added by Artur Hefczyc TigaseTeam over 4 years ago

you can upgrade it but you need to update all the Tigase jars to ensure everything works on a new version. I suggest to use our nightly installation builds which contain all the recent code in a correct versions.

Added by Matt Morten over 4 years ago

My apologies, I missed the following information:

The server actually did indeed register the disconnect at 30 mins later:

2014-07-16 12:49:41.827 [in_2-c2s]         SocketThread.addSocketServicePriv()  FINEST: Adding to waiting: c2s@moomin2.local/192.168.140.134_5222_192.168.140.134_50989, type: accept, Socket: TLS: c2s@moomin2.local/192.168.140.134_5222_192.168.140.134_50989 Socket[addr=/192.168.140.134,port=50989,localport=5222], jid: vdxmdgfcwbqdvhoudllahxwrwdyk5zut#alice@moomin2.local/1040087706726959010

…snip…

2014-07-16 13:15:12.036 [hostnames]        UserRepoRepository.reload()        CONFIG:   All loaded items: {moomin2.local=Domain: moomin2.local, enabled: true, anonym: true, register: true, maxusers: 0,
2014-07-16 13:16:12.036 [hostnames]        UserRepoRepository.reload()        CONFIG:   All loaded items: {moomin2.local=Domain: moomin2.local, enabled: true, anonym: true, register: true, maxusers: 0,
2014-07-16 13:17:12.037 [hostnames]        UserRepoRepository.reload()        CONFIG:   All loaded items: {moomin2.local=Domain: moomin2.local, enabled: true, anonym: true, register: true, maxusers: 0,
2014-07-16 13:18:12.036 [hostnames]        UserRepoRepository.reload()        CONFIG:   All loaded items: {moomin2.local=Domain: moomin2.local, enabled: true, anonym: true, register: true, maxusers: 0,
2014-07-16 13:19:12.037 [hostnames]        UserRepoRepository.reload()        CONFIG:   All loaded items: {moomin2.local=Domain: moomin2.local, enabled: true, anonym: true, register: true, maxusers: 0,
2014-07-16 13:19:29.878 [Watchdog - c2s]   IOService.writeData()              FINEST:   Socket: TLS: c2s@moomin2.local/192.168.140.134_5222_192.168.140.134_50989 Socket[unconnected], Writing data (1): 
2014-07-16 13:19:29.879 [Watchdog - c2s]   IOService.writeData()              FINER:    Data writing exception c2s@moomin2.local/192.168.140.134_5222_192.168.140.134_50989
java.nio.channels.ClosedChannelException
        at sun.nio.ch.SocketChannelImpl.ensureWriteOpen(SocketChannelImpl.java:265)
        at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:456)
        at tigase.io.SocketIO.write(SocketIO.java:440)
        at tigase.io.TLSIO.writeBuff(TLSIO.java:585)
        at tigase.io.TLSIO.write(TLSIO.java:427)
        at tigase.net.IOService.writeData(IOService.java:1277)
        at tigase.xmpp.XMPPIOService.writeRawData(XMPPIOService.java:347)
        at tigase.server.ConnectionManager$Watchdog$1.check(ConnectionManager.java:1558)
        at tigase.server.ConnectionManager.doForAllServices(ConnectionManager.java:1015)
        at tigase.server.ConnectionManager$Watchdog.run(ConnectionManager.java:1517)
        at java.lang.Thread.run(Thread.java:745)
2014-07-16 13:19:29.879 [Watchdog - c2s]   IOService.forceStop()              FINER:    Socket: TLS: c2s@moomin2.local/192.168.140.134_5222_192.168.140.134_50989 Socket[unconnected], Force stop called.
2014-07-16 13:19:29.879 [Watchdog - c2s]   IOService.forceStop()              FINER:    Calling stop on the listener: tigase.cluster.ClientConnectionClustered@6b5e1fc5
2014-07-16 13:19:29.881 [Watchdog - c2s]   ConnectionManager.serviceStopped()  FINER:   [[c2s]] Connection stopped: c2s@moomin2.local/192.168.140.134_5222_192.168.140.134_50989, type: accept, Socket: T
2014-07-16 13:19:29.881 [Watchdog - c2s]   ClientConnectionManager.xmppStreamClosed()  FINER: Stream closed: c2s@moomin2.local/192.168.140.134_5222_192.168.140.134_50989
2014-07-16 13:19:29.882 [Watchdog - c2s]   ClientConnectionManager.xmppStreamClosed()  FINE: Service stopped, sending packet: from=null, to=null, DATA=<iq from="c2s@moomin2.local/192.168.140.134_5222_1
2014-07-16 13:19:29.882 [in_23-message-router]  MessageRouter.processPacket()  FINEST:  Processing packet: from=null, to=null, DATA=<iq from="c2s@moomin2.local/192.168.140.134_5222_192.168.140.134_5098
2014-07-16 13:19:29.882 [in_23-message-router]  MessageRouter.getLocalComponent()  FINEST: Called for : sess-man@moomin2.local
2014-07-16 13:19:29.882 [Watchdog - c2s]   IOService.forceStop()              FINER:    Socket: TLS: c2s@moomin2.local/192.168.140.134_5222_192.168.140.134_50989 Socket[unconnected], Force stop called.
2014-07-16 13:19:29.882 [in_23-message-router]  MessageRouter.getLocalComponent()  FINEST: Called for : sess-man@moomin2.local
2014-07-16 13:19:29.882 [Watchdog - c2s]   IOService.forceStop()              FINER:    Service listener is null: TLS: c2s@moomin2.local/192.168.140.134_5222_192.168.140.134_50989 Socket[unconnected]
2014-07-16 13:19:29.882 [in_23-message-router]  MessageRouter.processPacket()  FINEST:  1. Packet will be processed by: sess-man@moomin2.local, from=null, to=null, DATA=<iq from="c2s@moomin2.local/192.
2014-07-16 13:19:29.883 [in_23-sess-man]   SessionManager.processCommand()    FINER:    STREAM_CLOSED command from: c2s@moomin2.local/192.168.140.134_5222_192.168.140.134_50989
2014-07-16 13:19:29.884 [in_2-message-router]  MessageRouter.processPacket()  FINEST:   Processing packet: from=sess-man@moomin2.local, to=c2s@moomin2.local/192.168.140.134_5222_192.168.140.134_50989, 
2014-07-16 13:19:29.885 [session-close Queue Worker 3]  SessionManager$SessionCloseProc.process()  FINEST: Executing connection close for: from=null, to=null, DATA=<iq from="c2s@moomin2.local/192.168.1
2014-07-16 13:19:29.886 [in_2-message-router]  MessageRouter.getLocalComponent()  FINEST: Called for : c2s@moomin2.local/192.168.140.134_5222_192.168.140.134_50989
2014-07-16 13:19:29.888 [in_2-message-router]  MessageRouter.getLocalComponent()  FINEST: None compId matches (fast lookup): c2s@moomin2.local/192.168.140.134_5222_192.168.140.134_50989, for map: {stat
2014-07-16 13:19:29.888 [in_2-message-router]  MessageRouter.getLocalComponent()  FINEST: Called for : c2s@moomin2.local/192.168.140.134_5222_192.168.140.134_50989
2014-07-16 13:19:29.888 [session-close Queue Worker 3]  SessionManager.closeConnection()  FINER: Stream closed from: c2s@moomin2.local/192.168.140.134_5222_192.168.140.134_50989
2014-07-16 13:19:29.888 [in_2-message-router]  MessageRouter.getLocalComponent()  FINEST: None compId matches (fast lookup): c2s@moomin2.local/192.168.140.134_5222_192.168.140.134_50989, for map: {stat
2014-07-16 13:19:29.888 [in_2-message-router]  MessageRouter.processPacket()  FINEST:   1. Packet will be processed by: c2s@moomin2.local, from=sess-man@moomin2.local, to=c2s@moomin2.local/192.168.140.
2014-07-16 13:19:29.888 [in_2-c2s]         ClientConnectionManager$StoppedHandler.responseReceived()  FINEST: Response for stop received...
2014-07-16 13:19:29.889 [session-close Queue Worker 3]  SessionManager.closeSession()  FINE: Closing connection for: vdxmdgfcwbqdvhoudllahxwrwdyk5zut#alice@moomin2.local/1040087706726959010
2014-07-16 13:19:29.889 [session-close Queue Worker 3]  SessionManager.closeSession()  FINE: Found parent session for: vdxmdgfcwbqdvhoudllahxwrwdyk5zut#alice@moomin2.local/1040087706726959010
2014-07-16 13:19:29.889 [session-close Queue Worker 3]  SessionManager.closeSession()  FINER: Number of user sessions: 1

So it seems it does indeed get a disconnect notification. However, with Resource strings it takes 30m and without it is instant. Strange.

Added by rushikesh deshpande about 4 years ago

hi ,

Can anyone solve the issue ? I am also getting the same error

Added by Wojciech Kapcia TigaseTeam about 4 years ago

I've reopened the ticket.

Added by Andrzej Wójcik IoT 1 CloudTigaseTeam about 4 years ago

I just checked once again if fix works properly using Tigase XMPP Server 7.0.0-SNAPSHOT and all is working fine (with and without StreamManagement enabled).

This was not fixed in 5.2.x releases so it may still be valid issue for them but 7.0.0 is going to be released soon and upgrade to new version will be suggested fix for this issue.

If you still have this issue with Tigase XMPP Server 7.0.0-SNAPSHOT please provide which version/release of Tigase XMPP Server you are using.

Added by rushikesh deshpande about 4 years ago

Hi

Sorry if this is not proper place to ask but I can not find much documentation related to Tigase 7.0.0 release. If I recall for tigase 5.2.3 release https://projects.tigase.org/projects/tigase-server/files was the download link. If you can give me any link related to 7.0.0 release that would be helpful.

Added by Andrzej Wójcik IoT 1 CloudTigaseTeam about 4 years ago

As Tigase XMPP Server 7.0.0 version is not yet released, I mentioned nightly build Tigase XMPP Server 7.0.0-SNAPSHOT which is build every night and recent builds you can find at http://build.tigase.org/nightlies/dists/

    (1-13/13)