Project

General

Profile

I hope to confirm that jaxmpp client won't send request again when it hasn't received tigase server's response as network interrupt

Rick Zhang
Added over 4 years ago

Hi:

Recently I use jaxmpp library to test performance of our tigase server.I spend a lot of time on reading jaxmpp source code yet.It's a bit complex and short of document:)

I test server proformance by jaxmpp client with bosh protocol,and use about 100 users to login concurrently.The result is strange:If I connect to our server which proxied by Nginx(http://server/http-bind),they can all login success;but if I connect to server in my local computer(http://localhost:5280/http-bind),always some users login fail.I research the source of client library deeply and write lots of log for tracing,then I found(below client and server are both in my local computer):

1、client receives the response of "resource bind" is the signal that login success;

2、always some client users in my test are stopping at the previous step:They can't receive response(resource bound) from server.This is the request xml:

request userJid:selenium9@performance1.com,body=robot

Then I see BoshWorker#run() is waiting here:

BufferedReader rd = new BufferedReader(new InputStreamReader(conn.getInputStream()));

and never stop as it hasn't been set timeout parameter.

I trace server log carefully,and accidental found this log:

2014-07-12 19:42:39.870 [pool-15-thread-5] BoshSession.processSocketPacket() INFO: Duplicated packet: from=null, to=null, DATA=robot, SIZE=259, XMLNS=http://jabber.org/protocol/httpbind, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=null

I am sure the server process this "resource bind" request twice,but the last time the response is terminated by BoshSession#isDuplicateMessage before sending out response.It means server treats it as a repeat request and won't send again.

Now my questions are below and I hope your help to confirm them:

1、Why the method #processSocketPacket is entered in twice?

2、I guess that the first response was failed as network interrupt(We all know http is not stable,even in localhost?) and server won't handle the interrupted fault itself.This duty may should be done by client,it means client should send this request again.Am I right?

3、Coincidently BoshWorker in jaxmpp library won't do this resend job.It only wait there forever because it hasn't set time out.Without changing its code,Jaxmpp library can't interrupt the waiting and send again if it can't receive response.am I right?

4、As stated at the begining,all user can login success if I connect to the server proxied by Nginx.If it means Nginx may guarantee response can be sent out?

5、If we should test the point:all user must login success in several seconds?Maybe login fail is a common thing,and only need client detector it and request again?Tigase server needn't to guarantee it.

Thank you for your help!


Replies (3)

Avatar?id=6023&size=32x32

Added by Artur Hefczyc TigaseTeam over 4 years ago

One possible reason why it fails (connection) is, if you run it locally you may exceed max number of connections. Most operating systems are configured to allow max 1024 connections by default. Actually on Linux, Mac OSX this is a max number of open files, and connections are counted as open files. And it is very easy to exceed this 1024. Especially with Bosh, which opens a new connections for each new request. I am not sure if this is what happens in your case but it is one of possible reasons.

I suggest to carefully trace log files on both - Tigase server and the JaXMPP client. If the resource bind if requested second time, you should be able to find the first request, you can trace the first request, whether it was called, and fully processed by the server, then if a response was sent back to the client and whether the client received it.

I guess the last part is missing - was not received by the client. I remember having a problem like this on Mac os ox a while ago and to be honest i could not solve it. The system somehow blocks transmission keeping data in network buffers.

Added by Rick Zhang over 4 years ago

Thank you.Today I spent the whole day to anlyase this problem and now I have some new information:

I only use 10 users login by 10 threads at the same time,and always one or two user can't login as he can't success to bind resource.Below is some jaxmpp client logs(I print them by myself) of two users:the first one is fail and the second one is success.Their logs both begin with "finish sasl".

fail user:

2014-07-13 19:29:21.453 [Thread-53]        BoshWorker.run()                   INFO:     user jid=user8@zk.hs.com,response xml:<body host="zhangkeasus" ack="2905365" xmlns:stream="http://etherx.jabber.org/streams" secure="true" xmlns="http://jabber.org/protocol/httpbind" from="zk.hs.com" xmpp:version="1.0" xmlns:xmpp="urn:xmpp:xbosh"><success xmlns="urn:ietf:params:xml:ns:xmpp-sasl"/></body>
2014-07-13 19:29:21.453 [Thread-78]        BoshWorker.run()                   INFO:     user jid=user8@zk.hs.com,request xml:<body sid="1d3afbcf-673b-4425-a873-5b86a8918584" rid="2905366" xmlns="http://jabber.org/protocol/httpbind"/>
2014-07-13 19:29:21.468 [Thread-79]        BoshWorker.run()                   INFO:     user jid=user8@zk.hs.com,request xml:<body to="zk.hs.com" sid="1d3afbcf-673b-4425-a873-5b86a8918584" xmlns:xmpp="urn:xmpp:xbosh" rid="2905367" xml:lang="en" xmlns="http://jabber.org/protocol/httpbind" from="user8@zk.hs.com" xmpp:restart="true"/>
2014-07-13 19:29:21.562 [Thread-79]        BoshWorker.run()                   INFO:     user jid=user8@zk.hs.com,response xml:<body host="zhangkeasus" ack="2905367" xmlns:stream="http://etherx.jabber.org/streams" secure="true" xmlns="http://jabber.org/protocol/httpbind" from="zk.hs.com" xmpp:version="1.0" xmlns:xmpp="urn:xmpp:xbosh"/>
2014-07-13 19:29:51.656 [Thread-78]        BoshWorker.run()                   INFO:     user jid=user8@zk.hs.com,response xml:<body host="zhangkeasus" ack="2905366" xmlns:stream="http://etherx.jabber.org/streams" secure="true" xmlns="http://jabber.org/protocol/httpbind" from="zk.hs.com" xmpp:version="1.0" xmlns:xmpp="urn:xmpp:xbosh"/>
2014-07-13 19:29:51.656 [Thread-190]       BoshWorker.run()                   INFO:     user jid=user8@zk.hs.com,request xml:<body sid="1d3afbcf-673b-4425-a873-5b86a8918584" rid="2905368" xmlns="http://jabber.org/protocol/httpbind"/>
2014-07-13 19:30:21.671 [Thread-190]       BoshWorker.run()                   INFO:     user jid=user8@zk.hs.com,response xml:<body host="zhangkeasus" ack="2905368" xmlns:stream="http://etherx.jabber.org/streams" secure="true" xmlns="http://jabber.org/protocol/httpbind" from="zk.hs.com" xmpp:version="1.0" xmlns:xmpp="urn:xmpp:xbosh"/>
2014-07-13 19:30:21.671 [Thread-199]       BoshWorker.run()                   INFO:     user jid=user8@zk.hs.com,request xml:<body sid="1d3afbcf-673b-4425-a873-5b86a8918584" rid="2905369" xmlns="http://jabber.org/protocol/httpbind"/>
2014-07-13 19:30:22.421 [Thread-201]       BoshWorker.run()                   INFO:     user jid=user8@zk.hs.com,request xml:<body sid="1d3afbcf-673b-4425-a873-5b86a8918584" rid="2905370" xmlns="http://jabber.org/protocol/httpbind"><message id="hOa6k" to="admin@zk.hs.com"><subject>test</subject><body>this is a test</body></message></body>
2014-07-13 19:30:22.421 [Thread-199]       BoshWorker.run()                   INFO:     user jid=user8@zk.hs.com,response xml:<body host="zhangkeasus" ack="2905369" xmlns:stream="http://etherx.jabber.org/streams" secure="true" xmlns="http://jabber.org/protocol/httpbind" from="zk.hs.com" xmpp:version="1.0" xmlns:xmpp="urn:xmpp:xbosh"/>
2014-07-13 19:30:22.531 [Thread-201]       BoshWorker.run()                   INFO:     user jid=user8@zk.hs.com,response xml:<body host="zhangkeasus" ack="2905370" xmlns:stream="http://etherx.jabber.org/streams" secure="true" xmlns="http://jabber.org/protocol/httpbind" from="zk.hs.com" xmpp:version="1.0" xmlns:xmpp="urn:xmpp:xbosh"><message id="hOa6k" type="error" xmlns="jabber:client" from="admin@zk.hs.com"><subject>test</subject><body>this is a test</body><error type="auth" code="401"><not-authorized xmlns="urn:ietf:params:xml:ns:xmpp-stanzas"/><text xml:lang="en" xmlns="urn:ietf:params:xml:ns:xmpp-stanzas">You must bind the resource first: http://www.xmpp.org/rfcs/rfc3920.html#bind</text></error></message></body>

success user:

2014-07-13 19:29:21.515 [Thread-56]        BoshWorker.run()                   INFO:     user jid=user7@zk.hs.com,response xml:<body host="zhangkeasus" ack="7638498" xmlns:stream="http://etherx.jabber.org/streams" secure="true" xmlns="http://jabber.org/protocol/httpbind" from="zk.hs.com" xmpp:version="1.0" xmlns:xmpp="urn:xmpp:xbosh"><success xmlns="urn:ietf:params:xml:ns:xmpp-sasl"/></body>
2014-07-13 19:29:21.531 [Thread-84]        BoshWorker.run()                   INFO:     user jid=user7@zk.hs.com,request xml:<body sid="872e7fc3-5920-4805-b1aa-33b8a5c62cc2" rid="7638499" xmlns="http://jabber.org/protocol/httpbind"/>
2014-07-13 19:29:21.531 [Thread-85]        BoshWorker.run()                   INFO:     user jid=user7@zk.hs.com,request xml:<body to="zk.hs.com" sid="872e7fc3-5920-4805-b1aa-33b8a5c62cc2" xmlns:xmpp="urn:xmpp:xbosh" rid="7638500" xml:lang="en" xmlns="http://jabber.org/protocol/httpbind" from="user7@zk.hs.com" xmpp:restart="true"/>
2014-07-13 19:29:21.687 [Thread-85]        BoshWorker.run()                   INFO:     user jid=user7@zk.hs.com,response xml:<body host="zhangkeasus" ack="7638499" xmlns:stream="http://etherx.jabber.org/streams" secure="true" xmlns="http://jabber.org/protocol/httpbind" from="zk.hs.com" xmpp:version="1.0" xmlns:xmpp="urn:xmpp:xbosh"><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-13 19:29:21.703 [Thread-104]       BoshWorker.run()                   INFO:     user jid=user7@zk.hs.com,request xml:<body sid="872e7fc3-5920-4805-b1aa-33b8a5c62cc2" rid="7638501" xmlns="http://jabber.org/protocol/httpbind"><iq xmlns="jabber:client" id="A9ejr" type="set"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind"><resource/></bind></iq></body>
2014-07-13 19:29:21.875 [Thread-104]       BoshWorker.run()                   INFO:     user jid=user7@zk.hs.com,response xml:<body host="zhangkeasus" ack="7638500" xmlns:stream="http://etherx.jabber.org/streams" secure="true" xmlns="http://jabber.org/protocol/httpbind" from="zk.hs.com" xmpp:version="1.0" xmlns:xmpp="urn:xmpp:xbosh"><iq xmlns="jabber:client" type="result" id="A9ejr" to="user7@zk.hs.com/tigase-127"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind"><jid>user7@zk.hs.com/tigase-127</jid></bind></iq></body>
2014-07-13 19:29:21.890 [Thread-131]       BoshWorker.run()                   INFO:     user jid=user7@zk.hs.com,request xml:<body sid="872e7fc3-5920-4805-b1aa-33b8a5c62cc2" rid="7638502" xmlns="http://jabber.org/protocol/httpbind"><iq id="weo36" type="get"><query xmlns="jabber:iq:roster"/></iq></body>
2014-07-13 19:29:21.890 [Thread-132]       BoshWorker.run()                   INFO:     user jid=user7@zk.hs.com,request xml:<body sid="872e7fc3-5920-4805-b1aa-33b8a5c62cc2" rid="7638503" xmlns="http://jabber.org/protocol/httpbind"><presence><c xmlns="http://jabber.org/protocol/caps" node="http://tigase.org" hash="sha-1" ver="GDJeU2PgGrtUeUH62yXz3492Sf0="/></presence></body>
2014-07-13 19:29:21.953 [Thread-84]        BoshWorker.run()                   INFO:     user jid=user7@zk.hs.com,response xml:<body host="zhangkeasus" ack="7638501" xmlns:stream="http://etherx.jabber.org/streams" secure="true" xmlns="http://jabber.org/protocol/httpbind" from="zk.hs.com" xmpp:version="1.0" xmlns:xmpp="urn:xmpp:xbosh"/>
2014-07-13 19:29:22.156 [Thread-131]       BoshWorker.run()                   INFO:     user jid=user7@zk.hs.com,response xml:<body host="zhangkeasus" ack="7638499" xmlns:stream="http://etherx.jabber.org/streams" secure="true" xmlns="http://jabber.org/protocol/httpbind" from="zk.hs.com" xmpp:version="1.0" xmlns:xmpp="urn:xmpp:xbosh"><iq xmlns="jabber:client" type="result" id="weo36" to="user7@zk.hs.com/tigase-127"><query xmlns="jabber:iq:roster"/></iq></body>
2014-07-13 19:29:22.265 [Thread-132]       BoshWorker.run()                   INFO:     user jid=user7@zk.hs.com,response xml:<body host="zhangkeasus" ack="7638502" xmlns:stream="http://etherx.jabber.org/streams" secure="true" xmlns="http://jabber.org/protocol/httpbind" from="zk.hs.com" xmpp:version="1.0" xmlns:xmpp="urn:xmpp:xbosh"><presence xmlns="jabber:client" to="user7@zk.hs.com" from="user7@zk.hs.com/tigase-127"><c node="http://tigase.org" ver="GDJeU2PgGrtUeUH62yXz3492Sf0=" hash="sha-1" xmlns="http://jabber.org/protocol/caps"/></presence></body>
2014-07-13 19:29:22.281 [Thread-162]       BoshWorker.run()                   INFO:     user jid=user7@zk.hs.com,request xml:<body sid="872e7fc3-5920-4805-b1aa-33b8a5c62cc2" rid="7638504" xmlns="http://jabber.org/protocol/httpbind"/>
2014-07-13 19:29:23.406 [Thread-184]       BoshWorker.run()                   INFO:     user jid=user7@zk.hs.com,request xml:<body sid="872e7fc3-5920-4805-b1aa-33b8a5c62cc2" rid="7638505" xmlns="http://jabber.org/protocol/httpbind"><message id="DBp6d" to="admin@zk.hs.com"><subject>test</subject><body>this is a test</body></message></body>
2014-07-13 19:29:23.437 [Thread-162]       BoshWorker.run()                   INFO:     user jid=user7@zk.hs.com,response xml:<body host="zhangkeasus" ack="7638503" xmlns:stream="http://etherx.jabber.org/streams" secure="true" xmlns="http://jabber.org/protocol/httpbind" from="zk.hs.com" xmpp:version="1.0" xmlns:xmpp="urn:xmpp:xbosh"/>
2014-07-13 19:29:53.437 [Thread-184]       BoshWorker.run()                   INFO:     user jid=user7@zk.hs.com,response xml:<body host="zhangkeasus" ack="7638504" xmlns:stream="http://etherx.jabber.org/streams" secure="true" xmlns="http://jabber.org/protocol/httpbind" from="zk.hs.com" xmpp:version="1.0" xmlns:xmpp="urn:xmpp:xbosh"/>
2014-07-13 19:29:53.437 [Thread-194]       BoshWorker.run()                   INFO:     user jid=user7@zk.hs.com,request xml:<body sid="872e7fc3-5920-4805-b1aa-33b8a5c62cc2" rid="7638506" xmlns="http://jabber.org/protocol/httpbind"/>

From the fail user's log,the request "rid=2905367" which after sasl should get response of stream-feature like the success user "rid=7638499" does.Normally after stream-feature,client should send resource bind request.Here the fail user hasn't received stream-feature,so he can't send resource bind message.It means he login fail.

I watch tigase server's log about handling the "rid=2905367" request.Fortuantely I found server has generated the right package,below is server's log:

2014-07-13 19:29:21.656 [pool-17-thread-1]  BoshIOService.writeRawData()      FINEST:   Writing to socket:
HTTP/1.1 200 OK^M
Content-Type: text/xml; charset=utf-8^M
Content-Length: 526^M
Access-Control-Allow-Origin: *^M
Access-Control-Allow-Methods: GET, POST, OPTIONS^M
Access-Control-Allow-Headers: Content-Type^M
Access-Control-Max-Age: 86400^M
Server: Tigase Bosh/0.0.0-0^M
^M
<body host="zhangkeasus" ack="2905366" xmlns:stream="http://etherx.jabber.org/streams" secure="true" xmlns="http://jabber.org/protocol/httpbind" from="zk.hs.com" xmpp:version="1.0" xmlns:xmpp="urn:xmpp:xbosh"><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-13 19:29:21.656 [socketReadThread-8]  SocketThread.run()              FINEST:   Selected keys = 0!!! a bug again?
2014-07-13 19:29:21.656 [in_1-bosh]        BoshSession.disconnected()         FINEST:   Setting inactivityTimer for 10: 6a28cd90-8b88-40b8-a2be-f3b10cc3e320
2014-07-13 19:29:21.656 [pool-17-thread-9]  BoshSession.processSocketPacket()  FINEST:  [0] Processing socket packet: from=null, to=null, DATA=<body rid="2272428" xmlns="http://jabber.org/protocol/httpbind" sid="b0ee562b-c965-4ced-8ba9-40a336b77e5b"/>, SIZE=108, XMLNS=http://jabber.org/protocol/httpbind, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=null

And I also see the interesting words "Selected keys = 0!!! a bug again?".Of course,the stream-feature package can't been send out because it hasn't call SocketIO.write() to send out data.I guess maybe you ever handled similar problem before,so I ask for your help here.

Avatar?id=6023&size=32x32

Added by Artur Hefczyc TigaseTeam over 4 years ago

  1. What OS do you run these tests on

  2. What exact Java do you use for your tests?

  3. What Tigase version do you use?

    (1-3/3)