ConnectionManager close the socket connection when the result of waiting.size() = 0 (#327)

Activities

binh vo opened 1 decade ago

The connection had been close with detail error as below:

2014-05-22 08:37:27.356 [ConnectionOpenThread]  ConnectionOpenThread.run()    FINEST:   OP_ACCEPT
2014-05-22 08:37:27.356 [ConnectionOpenThread]  ConnectionOpenThread.run()    FINER:    Registered new client socket: java.nio.channels.SocketChannel[connected local=/10.26.74.248:5222 remote=/10.26.119.6:32487]
2014-05-22 08:37:27.358 [ConnectionOpenThread]  ConnectionManager$ConnectionListenerImpl.accept()  FINEST: Accept called for service: null@null
2014-05-22 08:37:27.358 [ConnectionOpenThread]  ConnectionManager.serviceStarted()  FINER: [[c2s]] Connection started: null, type: accept, Socket: nullSocket[addr=/10.26.119.6,port=32487,localport=5222], jid: null
2014-05-22 08:37:27.359 [ConnectionOpenThread]  SocketThread.addSocketServicePriv()  FINEST: Adding to waiting: c2s@xmpp-dv-msdc03.ds.dtveng.net/10.26.74.248_5222_10.26.119.6_32487, type: accept, Socket: c2s@xmpp-dv-msdc03.ds.dtveng.net/10.26.74.248_5222_10.26.119.6_32487 Socket[addr=/10.26.119.6,port=32487,localport=5222], jid: null
2014-05-22 08:37:27.359 [socketReadThread-6]  SocketThread.run()              FINEST:   Selector AWAKE: sun.nio.ch.EPollSelectorImpl@1d6747c7
2014-05-22 08:37:27.359 [socketReadThread-6]  SocketThread.addAllWaiting()    FINEST:   waiting.size(): 1
2014-05-22 08:37:27.359 [socketReadThread-6]  SocketThread.addAllWaiting()    FINEST:   ADDED OP_READ: 10.26.74.248_5222_10.26.119.6_32487
2014-05-22 08:37:27.359 [socketReadThread-6]  SocketThread.run()              FINEST:   Selector AWAKE: sun.nio.ch.EPollSelectorImpl@1d6747c7
2014-05-22 08:37:27.359 [socketReadThread-6]  SocketThread.run()              FINEST:   AWAKEN: 10.26.74.248_5222_10.26.119.6_32487, ready for READING, readyOps() = 1
2014-05-22 08:37:27.359 [socketReadThread-6]  SocketThread.addAllWaiting()    FINEST:   waiting.size(): 0
2014-05-22 08:37:27.360 [pool-16-thread-1]  IOService.isConnected()           FINEST:   Socket: c2s@xmpp-dv-msdc03.ds.dtveng.net/10.26.74.248_5222_10.26.119.6_32487 Socket[addr=/10.26.119.6,port=32487,localport=5222], Connected: true, id: c2s@xmpp-dv-msdc03.ds.dtveng.net/10.26.74.248_5222_10.26.119.6_32487
2014-05-22 08:37:27.360 [pool-16-thread-1]  IOService.readData()              FINEST:   Socket: c2s@xmpp-dv-msdc03.ds.dtveng.net/10.26.74.248_5222_10.26.119.6_32487 Socket[addr=/10.26.119.6,port=32487,localport=5222], Exception reading data
java.io.EOFException: Channel has been closed.
	at tigase.io.SocketIO.read(SocketIO.java:309)
	at tigase.net.IOService.readData(IOService.java:992)
	at tigase.xmpp.XMPPIOService.processSocketData(XMPPIOService.java:524)
	at tigase.net.IOService.call(IOService.java:262)
	at tigase.net.IOService.call(IOService.java:103)
	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:724)
2014-05-22 08:37:27.360 [pool-16-thread-1]  IOService.forceStop()             FINER:    Socket: c2s@xmpp-dv-msdc03.ds.dtveng.net/10.26.74.248_5222_10.26.119.6_32487 Socket[addr=/10.26.119.6,port=32487,localport=5222], Force stop called...
2014-05-22 08:37:27.360 [pool-16-thread-1]  IOService.forceStop()             FINER:    Calling stop on: c2s@xmpp-dv-msdc03.ds.dtveng.net/10.26.74.248_5222_10.26.119.6_32487 Socket[addr=/10.26.119.6,port=32487,localport=5222]
2014-05-22 08:37:27.360 [pool-16-thread-1]  IOService.forceStop()             FINER:    Calling stop on the listener: tigase.cluster.ClientConnectionClustered@6a850415
2014-05-22 08:37:27.360 [pool-16-thread-1]  ConnectionManager.serviceStopped()  FINER:  [[c2s]] Connection stopped: c2s@xmpp-dv-msdc03.ds.dtveng.net/10.26.74.248_5222_10.26.119.6_32487, type: accept, Socket: c2s@xmpp-dv-msdc03.ds.dtveng.net/10.26.74.248_5222_10.26.119.6_32487 Socket[unconnected], jid: null
2014-05-22 08:37:27.360 [pool-16-thread-1]  ClientConnectionManager.xmppStreamClosed()  FINER: Stream closed: c2s@xmpp-dv-msdc03.ds.dtveng.net/10.26.74.248_5222_10.26.119.6_32487
2014-05-22 08:37:27.360 [pool-16-thread-1]  IOService.isConnected()           FINEST:   Socket: c2s@xmpp-dv-msdc03.ds.dtveng.net/10.26.74.248_5222_10.26.119.6_32487 Socket[unconnected], Connected: false, id: c2s@xmpp-dv-msdc03.ds.dtveng.net/10.26.74.248_5222_10.26.119.6_32487
2014-05-22 08:37:27.360 [ResultsListener-socketWriteThread-6]  IOService.isConnected()  FINEST: Socket: c2s@xmpp-dv-msdc03.ds.dtveng.net/10.26.74.248_5222_10.26.119.6_32487 Socket[unconnected], Connected: false, id: c2s@xmpp-dv-msdc03.ds.dtveng.net/10.26.74.248_5222_10.26.119.6_32487
2014-05-22 08:37:27.360 [ResultsListener-socketWriteThread-6]  SocketThread$ResultsListener.run()  FINEST: REMOVED: 10.26.74.248_5222_10.26.119.6_32487

My question is:

Why the error had been log as FINEST level since it closes the connection? The error happens when we try to send big message (22kB) to the user.

Artur Hefczyc commented 1 decade ago

The waiting.size() = 0 has nothing to do with connection close. And the closed connection is not considered as an error. This is just a normal thing form the server point of view. Clients open and close connections hundreds times per second and it is rarely an error. Therefore, Tigase does not report a closed connection as an error.

22kB message size is hardly considered as a big message. Tigase deals with much larger packets such as vcards with photos which can easily be more than 1MB. Therefore I doubt it has anything to do with sending a big message from the server to a client. Please also note, the connection close was disconnected during socket read attempt not write, so Tigase was not sending any data to a client.

binh vo commented 1 decade ago

Thank you Artur for quick response. I'll try to find out the root cause of this issue.

Type	Question
Priority	Major
Assignee	Artur Hefczyc
RedmineID	1983

Issue Votes (0)

Watchers (0)

Reference

tigase/_server/server-core#327