Race condition issue in StreamManagementIOProcessor (#418)

Activities

Daniele Ricci opened 10 years ago

This was triggered by massive concurrent connection/disconnection tests while trying to reproduce the issue described here: https://projects.tigase.org/boards/4/topics/4029

2015-01-22 10:33:27.791 [pool-12-thread-1]  ClientConnectionManager.xmppStreamClosed()  FINER: Stream closed: c2s@localhost/198.211.127.209_5999_217.50.107.28_58326
2015-01-22 10:33:27.791 [pool-12-thread-1]  ClientConnectionManager.xmppStreamClosed()  FINER: Stream closed: c2s@localhost/198.211.127.209_5999_217.50.107.28_58326
2015-01-22 10:33:27.791 [pool-12-thread-1]  XMPPIOService.processSocketData()  INFO:    c2s@localhost/198.211.127.209_5999_217.50.107.28_58326, type: accept, Socket: ZLIB: TLS: c2s@localhost/198.211.127.209_5999_217.50.107.28_58326 Socket[unconnected], jid: 08c10d754467adea2a5cc6af261208d6dfb7ab5b@beta.kontalk.net/d3fd96ae8a2f5357, Incorrect XML data: <presence id='3i0Q1-517' type='unavailable'></presence><a xmlns='urn:xmpp:sm:3' h='11'/></stream:stream>, stopping connection: c2s@localhost/198.211.127.209_5999_217.50.107.28_58326, exception:
java.lang.NullPointerException
        at tigase.server.xmppclient.StreamManagementIOProcessor.processIncoming(StreamManagementIOProcessor.java:197)
        at tigase.xmpp.XMPPIOService.addReceivedPacket(XMPPIOService.java:638)
        at tigase.xmpp.XMPPIOService.processSocketData(XMPPIOService.java:746)
        at tigase.net.IOService.call(IOService.java:261)
        at tigase.net.IOService.call(IOService.java:94)
        at java.util.concurrent.FutureTask.run(FutureTask.java:262)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
        at java.util.concurrent.FutureTask.run(FutureTask.java:262)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:745)
2015-01-22 10:33:27.792 [pool-12-thread-1]  StreamManagementIOProcessor.serviceStopped()  FINEST: c2s@localhost/198.211.127.209_5999_217.50.107.28_58326, type: accept, Socket: ZLIB: TLS: c2s@localhost/198.211.127.209_5999_217.50.107.28_58326 Socket[unconnected], jid: 08c10d754467adea2a5cc6af261208d6dfb7ab5b@beta.kontalk.net/d3fd96ae8a2f5357, service stopped - resumption disabled, sending unacked packets
2015-01-22 10:33:27.792 [pool-12-thread-1]  ConnectionManager.serviceStopped()  FINER:  [[c2s]] Connection stopped: c2s@localhost/198.211.127.209_5999_217.50.107.28_58326, type: accept, Socket: ZLIB: TLS: c2s@localhost/198.211.127.209_5999_217.50.107.28_58326 Socket[unconnected], jid: 08c10d754467adea2a5cc6af261208d6dfb7ab5b@beta.kontalk.net/d3fd96ae8a2f5357
2015-01-22 10:33:27.792 [pool-12-thread-1]  ConnectionManager.serviceStopped()  FINER:  [[c2s]] Attempt to stop incorrect service: c2s@localhost/198.211.127.209_5999_217.50.107.28_58326, type: accept, Socket: ZLIB: TLS: c2s@localhost/198.211.127.209_5999_217.50.107.28_58326 Socket[unconnected], jid: 08c10d754467adea2a5cc6af261208d6dfb7ab5b@beta.kontalk.net/d3fd96ae8a2f5357
2015-01-22 10:33:27.792 [pool-12-thread-1]  ClientConnectionManager.xmppStreamClosed()  FINER: Stream closed: c2s@localhost/198.211.127.209_5999_217.50.107.28_58326

Andrzej Wójcik (Tigase) commented 10 years ago

I took me a while to find out cause of this issue and it appears that it was caused by the fact that we closed XMPP stream just after parsing </stream:stream> but before processing received packets just before </stream:stream>. If in this not processed packets was packet then this NPE occured when they were processed after stream being closed.

As this premature close of stream could lead also to other packets not being processed properly, I delayed stream close to be done after packets are processed by @ClientConnectionManager@. I'm not sure, if this will not cause stream to not be closed properly due premature close of TCP connection by XMPP client.

Daniele Ricci commented 10 years ago

Thanks!

Type	Bug
Priority	Normal
Assignee	Artur Hefczyc
RedmineID	2626
Spent time	21h

Issue Votes (0)

Watchers (0)

Reference

tigase/_server/server-core#418