Project

General

Profile

CloseChannelException when resource bind makes client can't login successful and jaxmpp isn't going on sending presence/roster request

Rick Zhang
Added over 4 years ago

Hi:

Recently I use jaxmpp client to login tigase server.I found that client can't login successfully when server failed to write back resoure bind data.The version is jaxmpp2.0.2 ecff682 and tigase-server-5.2.0 48635d0 and client and server are all in my local Mac.

Here is the log of the failure user when ask resource bind:

2014-07-16 17:59:22.469 [Thread-130] BoshWorker.run() INFO: user jid=user2@zk.hs.com,request xml:

but the response from server is:

014-07-16 17:59:52.568 [Thread-130] BoshWorker.run() INFO: user jid=user2@zk.hs.com,response xml:

The response is an empty message and is sent after 30 seconds.I check server's log and found the correct response has been generated but can't be wrote as CloseChannelException:

2014-07-16 17:59:22.562 [in_10-bosh]       BoshSession.processPacket()        FINEST:   [1] Processing packet: from=sess-man@hf22.sumilux.com, to=bosh@hf22.sumilux.com/aa89b689-3a67-43bf-bb86-50f2777142c1, DATA=<iq xmlns="jabber:client" id="am6e3" type="result" to="user2@zk.hs.com/tigase-10"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind"><jid>user2@zk.hs.com/tigase-10</jid></bind></iq>, SIZE=177, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=result
2014-07-16 17:59:22.562 [pool-17-thread-30]  XMPPDomBuilderHandler.startElement()  FINEST: Element attributes values: null
2014-07-16 17:59:22.563 [in_10-bosh]       BoshSessionCache.set()             FINEST:   SET, id = bosh-resource-bind, DATA: [<iq xmlns="jabber:client" id="am6e3" type="result" to="user2@zk.hs.com/tigase-10"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind"><jid>user2@zk.hs.com/tigase-10</jid></bind></iq>]

........

2014-07-16 17:59:22.560 [pool-17-thread-5]  XMPPDomBuilderHandler.endElement()  FINEST: Adding new request: <body xmlns="http://jabber.org/protocol/httpbind" rid="2930206" sid="aa89b689-3a67-43bf-bb86-50f2777142c1"><iq xmlns="jabber:client" id="am6e3" type="set"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind"><resource/></bind></iq></body>
2014-07-16 17:59:22.561 [pool-17-thread-5]  XMPPIOService.processSocketData()  FINEST:  bosh@hf22.sumilux.com/127.0.0.1_5280_127.0.0.1_50776, type: accept, Socket: bosh@hf22.sumilux.com/127.0.0.1_5280_127.0.0.1_50776 Socket[addr=/127.0.0.1,port=50776,localport=5280], jid: null, Read packet: <body xmlns="http://jabber.org/protocol/httpbind" rid="2930206" sid="aa89b689-3a67-43bf-bb86-50f2777142c1"><iq xmlns="jabber:client" id="am6e3" type="set"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind"><resource/></bind></iq></body>
2014-07-16 17:59:22.561 [pool-17-thread-5]  SocketIO.read()                   FINER:    Read from channel 0 bytes, bosh@hf22.sumilux.com/127.0.0.1_5280_127.0.0.1_50776 Socket[addr=/127.0.0.1,port=50776,localport=5280]
2014-07-16 17:59:22.562 [pool-17-thread-5]  IOService.isConnected()           FINEST:   Socket: bosh@hf22.sumilux.com/127.0.0.1_5280_127.0.0.1_50776 Socket[addr=/127.0.0.1,port=50776,localport=5280], Connected: true, id: bosh@hf22.sumilux.com/127.0.0.1_5280_127.0.0.1_50776
2014-07-16 17:59:22.563 [pool-17-thread-5]  BoshConnectionManager.processSocketData()  FINER: Processing packet: body, type: null
2014-07-16 17:59:22.564 [pool-17-thread-5]  BoshConnectionManager.processSocketData()  FINEST: Processing socket data: from=null, to=null, DATA=<body xmlns="http://jabber.org/protocol/httpbind" rid="2930206" sid="aa89b689-3a67-43bf-bb86-50f2777142c1"><iq xmlns="jabber:client" id="am6e3" type="set"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind"><resource/></bind></iq></body>, SIZE=232, XMLNS=http://jabber.org/protocol/httpbind, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=null
2014-07-16 17:59:22.564 [pool-17-thread-5]  BoshSession.processSocketPacket()  FINEST:  [1] Processing socket packet: from=null, to=null, DATA=<body xmlns="http://jabber.org/protocol/httpbind" rid="2930206" sid="aa89b689-3a67-43bf-bb86-50f2777142c1"><iq xmlns="jabber:client" id="am6e3" type="set"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind"><resource/></bind></iq></body>, SIZE=232, XMLNS=http://jabber.org/protocol/httpbind, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=null
2014-07-16 17:59:22.565 [pool-17-thread-5]  BoshSession.processSocketPacket()  FINEST:  Canceling inactivityTimer: aa89b689-3a67-43bf-bb86-50f2777142c1
2014-07-16 17:59:22.566 [pool-17-thread-5]  BoshSession.processSocketPacket()  FINEST:  Setting waitTimer for 30: aa89b689-3a67-43bf-bb86-50f2777142c1
2014-07-16 17:59:22.567 [pool-17-thread-5]  BoshSession.processSocketPacket()  INFO:    Duplicated packet: from=null, to=null, DATA=<body xmlns="http://jabber.org/protocol/httpbind" rid="2930206" sid="aa89b689-3a67-43bf-bb86-50f2777142c1"><iq xmlns="jabber:client" id="am6e3" type="set"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind"><resource/></bind></iq></body>, SIZE=232, XMLNS=http://jabber.org/protocol/httpbind, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=null
2014-07-16 17:59:22.568 [pool-17-thread-5]  BoshSession.processSocketPacket()  INFO:    rid=2930206,start sendbody
2014-07-16 17:59:22.570 [pool-17-thread-5]  BoshSession.sendBody()            FINEST:   Canceling queue timer: aa89b689-3a67-43bf-bb86-50f2777142c1
2014-07-16 17:59:22.571 [pool-17-thread-5]  BoshSession.sendBody()            FINEST:   Canceling waitTimer: aa89b689-3a67-43bf-bb86-50f2777142c1
2014-07-16 17:59:22.572 [pool-17-thread-5]  BoshIOService.writeRawData()      FINEST:   Writing to socket:
2014-07-16 17:59:22.572 [pool-17-thread-5]  IOService.writeData()             FINEST:   Socket: bosh@hf22.sumilux.com/127.0.0.1_5280_127.0.0.1_50759 Socket[addr=/127.0.0.1,port=50759,localport=5280], Writing data: 663
2014-07-16 17:59:22.572 [pool-17-thread-5]  SocketIO.write()                  FINER:    SOCKET - Writing data, remaining: 663, bosh@hf22.sumilux.com/127.0.0.1_5280_127.0.0.1_50759 Socket[addr=/127.0.0.1,port=50759,localport=5280]
2014-07-16 17:59:22.573 [pool-17-thread-5]  IOService.writeData()             FINER:    Data writing exception bosh@hf22.sumilux.com/127.0.0.1_5280_127.0.0.1_50759
java.nio.channels.ClosedChannelException
        at sun.nio.ch.SocketChannelImpl.ensureWriteOpen(SocketChannelImpl.java:265)
        at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:474)
        at tigase.io.SocketIO.write(SocketIO.java:439)
        at tigase.net.IOService.writeData(IOService.java:1264)
        at tigase.xmpp.XMPPIOService.writeRawData(XMPPIOService.java:315)
        at tigase.server.bosh.BoshIOService.writeRawData(BoshIOService.java:327)
        at tigase.server.ConnectionManager.writeRawData(ConnectionManager.java:1130)
        at tigase.server.bosh.BoshConnectionManager.writeRawData(BoshConnectionManager.java:350)
        at tigase.server.bosh.BoshSession.sendBody(BoshSession.java:996)
        at tigase.server.bosh.BoshSession.processSocketPacket(BoshSession.java:563)
        at tigase.server.bosh.BoshConnectionManager.processSocketData(BoshConnectionManager.java:249)
        at tigase.server.ConnectionManager.packetsReady(ConnectionManager.java:438)
        at tigase.server.ConnectionManager.packetsReady(ConnectionManager.java:1)
        at tigase.net.IOService.call(IOService.java:264)
        at tigase.net.IOService.call(IOService.java:1)
        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)
2014-07-16 17:59:22.573 [pool-17-thread-5]  IOService.forceStop()             FINER:    Socket: bosh@hf22.sumilux.com/127.0.0.1_5280_127.0.0.1_50759 Socket[addr=/127.0.0.1,port=50759,localport=5280], Force stop called...
2014-07-16 17:59:22.574 [pool-17-thread-5]  IOService.forceStop()             FINER:    Service listener is null: bosh@hf22.sumilux.com/127.0.0.1_5280_127.0.0.1_50759 Socket[addr=/127.0.0.1,port=50759,localport=5280]
2014-07-16 17:59:22.574 [pool-17-thread-5]  SocketThread.addSocketServicePriv()  FINEST: Adding to waiting: bosh@hf22.sumilux.com/127.0.0.1_5280_127.0.0.1_50759, type: accept, Socket: bosh@hf22.sumilux.com/127.0.0.1_5280_127.0.0.1_50759 Socket[addr=/127.0.0.1,port=50759,localport=5280], jid: null
2014-07-16 17:59:22.575 [pool-17-thread-5]  IOService.forceStop()             FINER:    Socket: bosh@hf22.sumilux.com/127.0.0.1_5280_127.0.0.1_50750 Socket[unconnected], Force stop called...
2014-07-16 17:59:22.576 [pool-17-thread-5]  IOService.forceStop()             FINER:    Calling stop on the listener: tigase.server.bosh.BoshConnectionManager@14d5a66a
2014-07-16 17:59:22.576 [pool-17-thread-5]  ConnectionManager.serviceStopped()  FINER:  [[bosh]] Connection stopped: bosh@hf22.sumilux.com/127.0.0.1_5280_127.0.0.1_50750, type: accept, Socket: bosh@hf22.sumilux.com/127.0.0.1_5280_127.0.0.1_50750 Socket[unconnected], jid: null
2014-07-16 17:59:22.577 [pool-17-thread-5]  ClientConnectionManager.xmppStreamClosed()  FINER: Stream closed: bosh@hf22.sumilux.com/127.0.0.1_5280_127.0.0.1_50750
2014-07-16 17:59:22.577 [pool-17-thread-5]  BoshSession.disconnected()        FINEST:   Disconnected called for: 127.0.0.1_5280_127.0.0.1_50759
2014-07-16 17:59:22.578 [pool-17-thread-5]  BoshSession.disconnected()        FINEST:   Canceling inactivityTimer: aa89b689-3a67-43bf-bb86-50f2777142c1
2014-07-16 17:59:22.785 [pool-17-thread-5]  IOService.isConnected()           FINEST:   Socket: bosh@hf22.sumilux.com/127.0.0.1_5280_127.0.0.1_50778 Socket[addr=/127.0.0.1,port=50778,localport=5280], Connected: true, id: bosh@hf22.sumilux.com/127.0.0.1_5280_127.0.0.1_50778
2014-07-16 17:59:22.786 [pool-17-thread-5]  SocketIO.read()                   FINER:    Read from channel -1 bytes, bosh@hf22.sumilux.com/127.0.0.1_5280_127.0.0.1_50778 Socket[addr=/127.0.0.1,port=50778,localport=5280]
2014-07-16 17:59:22.787 [pool-17-thread-5]  IOService.isConnected()           FINEST:   Socket: bosh@hf22.sumilux.com/127.0.0.1_5280_127.0.0.1_50778 Socket[addr=/127.0.0.1,port=50778,localport=5280], Connected: false, id: bosh@hf22.sumilux.com/127.0.0.1_5280_127.0.0.1_50778

Now my question is:

CloseChannelException may be very normal in bosh,but why tigase-server send back an empty response to client?If server doesn't response at all,client may know that it should send this request again.But now client won't send request any more except "empty http-bind".Here is part client log of the failure user(request message is marked as "request xml" before "" and response is marked as "response xml" before "" too):

.......
2014-07-16 17:59:22.233 [Thread-78]        BoshWorker.run()                   INFO:     user jid=user2@zk.hs.com,response xml:<body xmlns="http://jabber.org/protocol/httpbind" secure="true" ack="2930203" from="zk.hs.com" xmpp:version="1.0" host="hf22.sumilux.com" xmlns:xmpp="urn:xmpp:xbosh" xmlns:stream="http://etherx.jabber.org/streams"/>
2014-07-16 17:59:22.464 [Thread-79]        BoshWorker.run()                   INFO:     user jid=user2@zk.hs.com,response xml:<body xmlns="http://jabber.org/protocol/httpbind" secure="true" ack="2930204" from="zk.hs.com" xmpp:version="1.0" host="hf22.sumilux.com" xmlns:xmpp="urn:xmpp:xbosh" xmlns:stream="http://etherx.jabber.org/streams"><stream:features xmlns="jabber:client"><ver xmlns="urn:xmpp:features:rosterver"/><starttls xmlns="urn:ietf:params:xml:ns:xmpp-tls"/><session xmlns="urn:ietf:params:xml:ns:xmpp-session"/><register xmlns="http://jabber.org/features/iq-register"/><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind"/></stream:features></body>
2014-07-16 17:59:22.465 [Thread-129]       BoshWorker.run()                   INFO:     user jid=user2@zk.hs.com,request xml:<body sid="aa89b689-3a67-43bf-bb86-50f2777142c1" rid="2930205" xmlns="http://jabber.org/protocol/httpbind"/>
2014-07-16 17:59:22.469 [Thread-130]       BoshWorker.run()                   INFO:     user jid=user2@zk.hs.com,request xml:<body sid="aa89b689-3a67-43bf-bb86-50f2777142c1" rid="2930206" xmlns="http://jabber.org/protocol/httpbind"><iq xmlns="jabber:client" id="am6e3" type="set"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind"><resource/></bind></iq></body>
2014-07-16 17:59:22.515 [Thread-129]       BoshWorker.run()                   INFO:     user jid=user2@zk.hs.com,response xml:<body xmlns="http://jabber.org/protocol/httpbind" secure="true" ack="2930205" from="zk.hs.com" xmpp:version="1.0" host="hf22.sumilux.com" xmlns:xmpp="urn:xmpp:xbosh" xmlns:stream="http://etherx.jabber.org/streams"/>
2014-07-16 17:59:52.568 [Thread-130]       BoshWorker.run()                   INFO:     user jid=user2@zk.hs.com,response xml:<body xmlns="http://jabber.org/protocol/httpbind" secure="true" from="zk.hs.com" xmpp:version="1.0" host="hf22.sumilux.com" xmlns:xmpp="urn:xmpp:xbosh" xmlns:stream="http://etherx.jabber.org/streams"/>
2014-07-16 17:59:52.569 [Thread-212]       BoshWorker.run()                   INFO:     user jid=user2@zk.hs.com,request xml:<body sid="aa89b689-3a67-43bf-bb86-50f2777142c1" rid="2930207" xmlns="http://jabber.org/protocol/httpbind"/>
2014-07-16 18:00:22.573 [Thread-212]       BoshWorker.run()                   INFO:     user jid=user2@zk.hs.com,response xml:<body xmlns="http://jabber.org/protocol/httpbind" secure="true" from="zk.hs.com" xmpp:version="1.0" host="hf22.sumilux.com" xmlns:xmpp="urn:xmpp:xbosh" xmlns:stream="http://etherx.jabber.org/streams"/>
2014-07-16 18:00:22.574 [Thread-221]       BoshWorker.run()                   INFO:     user jid=user2@zk.hs.com,request xml:<body sid="aa89b689-3a67-43bf-bb86-50f2777142c1" rid="2930208" xmlns="http://jabber.org/protocol/httpbind"/>
2014-07-16 18:00:32.204 [Thread-222]       BoshWorker.run()                   INFO:     user jid=user2@zk.hs.com,request xml:<body sid="aa89b689-3a67-43bf-bb86-50f2777142c1" rid="2930209" xmlns="http://jabber.org/protocol/httpbind"><message id="xF2cb" to="admin@zk.hs.com"><subject>test</subject><body>this is a test by user2@zk.hs.com</body></message></body>
2014-07-16 18:00:32.208 [Thread-221]       BoshWorker.run()                   INFO:     user jid=user2@zk.hs.com,response xml:<body xmlns="http://jabber.org/protocol/httpbind" secure="true" ack="2930209" from="zk.hs.com" xmpp:version="1.0" host="hf22.sumilux.com" xmlns:xmpp="urn:xmpp:xbosh" xmlns:stream="http://etherx.jabber.org/streams"/>

Thank you for your help!


Replies (4)

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

Hi,

I think that issue you are expiriencing is caused by value of bosh/concurrent-requests setting, which by default is 2. It means that only 2 concurrent HTTP request are allowed for particular BOSH session. This setting might be changed in etc/init.properties file.

I would suggest to try adding following line to etc/init.properties file to increase concurrency to 8:

bosh/concurrent-requests[I]=8

Added by Rick Zhang over 4 years ago

Thank you for your answer.What a pity the "bosh/concurrent-requests" isn't useful.

I have added the config "bosh/concurrent-requests[I]=8" to /etc/init.properties and from client log we can see the response of bosh is request=8

2014-07-21 10:31:53.015 [Thread-23] BoshWorker.run() INFO: user jid=user10@zk.hs.com,request xml:

2014-07-21 10:31:53.211 [Thread-23] BoshWorker.run() INFO: user jid=user10@zk.hs.com,response xml:

But the result is still the same:

2014-07-21 10:31:53.894 [Thread-117] BoshWorker.run() INFO: user jid=user10@zk.hs.com,request xml:

2014-07-21 10:31:53.897 [Thread-118] BoshWorker.run() INFO: user jid=user10@zk.hs.com,request xml:

2014-07-21 10:31:53.944 [Thread-117] BoshWorker.run() INFO: user jid=user10@zk.hs.com,response xml:

2014-07-21 10:32:24.111 [Thread-118] BoshWorker.run() INFO: user jid=user10@zk.hs.com,response xml:

Besides,I don't understand why this problem may caused by "bosh/concurrent-requests setting"?Can you explain more?

Added by Rick Zhang over 4 years ago

In the chapters "Broken Connections" of "XEP-0124"(http://xmpp.org/extensions/xep-0124.html#rids-broken),it said:

_The connection manager SHOULD remember the 'rid' and the associated HTTP response body of the client's most recent requests which were not session pause requests (see Inactivity) and which did not result in an HTTP or binding error.

If the network connection is broken or closed before the client receives a response to a request from the connection manager, then the client MAY resend an exact copy of the original request. Whenever the connection manager receives a request with a 'rid' that it has already received, it SHOULD return an HTTP 200 (OK) response that includes the buffered copy of the original XML response to the client (i.e., a wrapper possessing appropriate attributes and optionally containing one or more XML payloads)._

In package "tigase.server.bosh" of tigase-server,I haven't saw any logic about this.Although this part is described by "SHOULD" and tigase doesn't need implement it,I also want to know how tigase server deals with "Broken Connections" when using Bosh.

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

I supposed that this issue might be caused by issue with bosh/concurrent-requests as it could lead to closing BOSH connections by Tigase XMPP Server if number of active BOSH connections per session would be excided. This would be visible as sending answers to client without content. Good example of this would be following content:

<body host="hf22.sumilux.com" xmlns:stream="http://etherx.jabber.org/streams" xmlns="http://jabber.org/protocol/httpbind" secure="true" from="zk.hs.com" xmpp:version="1.0" xmlns:xmpp="urn:xmpp:xbosh"/>

Tigase XMPP Server contains logic which handles broken connection case but in slightly different way.

In case HTTP connection is lost before response is delivered to client, server on next connection from client (it maybe next established connection or next available connection which was already established by client) will deliver previously undelivered packets but may also contain other packets which need to be delivered to client, which appeared in meanwhile.

    (1-4/4)