search

esl / MongooseIM

MongooseIM is Erlang Solutions' robust, scalable and efficient XMPP server, aimed at large installations. Specifically designed for enterprise purposes, it is fault-tolerant and can utilise the resources of multiple clustered machines.
Other
1.64k stars 422 forks source link

Problem with authentication #306

Closed janjiss closed 9 years ago

janjiss commented 9 years ago

Hey guys, I get this error whenever I try to start bosh session.

2014-11-04 16:23:53.095 [warning] <0.521.0>@mod_bosh:forward_body:311 session not found!
{xmlel,<<"body">>,[{<<"xmlns">>,<<"http://jabber.org/protocol/httpbind">>},{<<"xmlns:xmpp">>,<<"urn:xmpp:xbosh">>},{<<"rid">>,<<"62968">>},{<<"xmpp:version">>,<<"1.0">>},{<<"sid">>,<<>>}],[{xmlel,<<"auth">>,[{<<"xmlns">>,<<"urn:ietf:params:xml:ns:xmpp-sasl">>},{<<"mechanism">>,<<"PLAIN">>}],[{xmlcdata,<<"X3JjX3p4ODRiZmMtMXFiM3RleHdqQGxvY2FsaG9zdABfcmNfeng4NGJmYy0xcWIzdGV4d2oAc2Fwa2FqYTIx">>}]}]}

I tried OS-X 1.4.0 package and also compiled package from master, only line of code changes after forward_body: I tried several auth methods and redis backend instead of mnesia and with no luck. Any ideas? Thanks

michalwski commented 9 years ago

What client library do you use? Could you send us what the client is sending to the server (from the very begging)?

janjiss commented 9 years ago

I am using RubyBOSH: https://github.com/skyfallsin/ruby_bosh Note, it worked for me when I was working with ejabberd server. This is what I got form clients logs:

Ruby-BOSH - SEND
[Tue Nov 04 16:31:19 2014]: <body rid="87641" xmlns="http://jabber.org/protocol/httpbind" xmpp:version="1.0" xmlns:xmpp="urn:xmpp:xbosh" wait="5" to="localhost" hold="3" window="5"/>
Ruby-BOSH - SEND
[Tue Nov 04 16:31:19 2014]: <body rid="87642" xmlns="http://jabber.org/protocol/httpbind" xmpp:version="1.0" xmlns:xmpp="urn:xmpp:xbosh" sid="">
  <auth xmlns="urn:ietf:params:xml:ns:xmpp-sasl" mechanism="PLAIN">X3JjX3p4ODRiZmMtMXFiM3RleHdqQGxvY2FsaG9zdABfcmNfeng4NGJmYy0xcWIzdGV4d2oAc2Fwa2FqYTIx</auth>
</body>
michalwski commented 9 years ago

Looks like the client doesn't work correctly. The second message sent form the client has empty sid attribute, that's why the server is not able to find your session.

janjiss commented 9 years ago

Seems that mongoose server does not like initial request, this is xml returned:

<body xmlns='http://jabber.org/protocol/httpbind' condition='undefined-condition' type='terminate'/>

Is MongooseIM XMPP protocol version different from Ejabberd?

erszcz commented 9 years ago

Yes, it is different from ejabberd's - it is reimplemented on top of Cowboy. MongooseIM doesn't support the full BOSH spec with respect to values of hold. Please use hold='1'. Moreover, window is not specified in XEP-0124 nor in XEP-0206.

I hope that adjusting hold will help - let us know what's your result.

EDIT: Of course it's not XMPP version that's different. It's the implementation of BOSH. Sorry for my sloppy reading.

janjiss commented 9 years ago

@michalwski Thanks for pointing me in right direction. @lavrin Thanks, you were right, this helped to get me pass first hump. MongooseIM Request/response on http-bind interface differ from ejabberd implementation and RubyBOSH is not working with correctly out of the box. I will need to hack on this library in order to make it comply with MongooseIM, Ill let you know the results once I am done. Will close this issue, since it is implementation detail of this specific lib.

janjiss commented 9 years ago

@michalslaski @lavrin Hey guys, I managed to get it working, but I wanted to ask for some advice - Is there a way for me to get some kind reference to protocol that you are using with flow explained? I got from code these actions:

initialize_bosh_session send_auth_request send_restart_request request_resource_binding send_session_request

The reason why I am asking this, is because it is semi-working. Sometimes it does and sometimes it does not. It's hard for me to get it right without knowing the flow Any help appreciated.

erszcz commented 9 years ago

The flow is the same as with regular XMPP over TCP (like: start stream / init bosh session, features, auth, features, bind, session). The factor which makes it more complex is that both sides have to encapsulate stanzas inside HTTP requests / replies. Keep in mind the rule: there must always be a connection open to the server. When the server replies with an empty response, the client ought to issue a new empty request, so that there's a channel for the server to send on. The server will reply with an empty response if it doesn't have anything sensible to send in wait time.

janjiss commented 9 years ago

Hey guys, sorry to keep nagging you, but I need assistance on resource binding request, but this as well might happen somewhere in restart of session request. The data generated by library to the server is like this:

<body rid="72885" xmlns="http://jabber.org/protocol/httpbind" xmpp:version="1.0" xmlns:xmpp="urn:xmpp:xbosh" sid="bb8f80c8826cd91b4492edbf2d5c1068cb73c743">
  <iq id="bind_34635" type="set" xmlns="jabber:client">
    <bind xmlns="urn:ietf:params:xml:ns:xmpp-bind">
      <resource>bosh_727</resource>
    </bind>
  </iq>
</body>

And Mongoose dies with following error:

2014-11-07 12:25:38.366 [debug] <0.572.0>@mod_bosh_socket:terminate:400 Closing session <<"6f60f745d2c5691dfa346c57f73fc5c8e720ea36">> in 'closing' state. Handlers: [] Pending: [{xmlstreamstart,<<"stream:stream">>,[{<<"xml:lang">>,"en"},{<<"xmlns">>,<<"jabber:client">>},{<<"xmlns:stream">>,<<"http://etherx.jabber.org/streams">>},{<<"id">>,"3411127855"},{<<"from">>,<<"localhost">>}]},{xmlel,<<"stream:error">>,[],[{xmlel,<<"host-unknown">>,[{<<"xmlns">>,<<"urn:ietf:params:xml:ns:xmpp-streams">>}],[]}]},{xmlstreamend,<<"stream:stream">>}]
2014-11-07 12:25:38.367 [error] <0.572.0> gen_fsm <0.572.0> in state closing terminated with reason: no case clause matching {[{xmlstreamstart,<<"stream:stream">>,[{<<"xml:lang">>,"en"},{<<"xmlns">>,<<"jabber:client">>},{<<"xmlns:stream">>,<<"http://etherx.jabber.org/streams">>},{<<"id">>,"3411127855"},{<<"from">>,<<"localhost">>}]},{xmlstreamend,<<"stream:stream">>}],[{xmlel,<<"stream:error">>,[],[{xmlel,<<"host-unknown">>,[{<<"xmlns">>,<<"urn:ietf:params:xml:ns:xmpp-streams">>}],[]}]}]} in mod_bosh_socket:bosh_wrap/3 line 872
2014-11-07 12:25:38.367 [error] <0.572.0> CRASH REPORT Process <0.572.0> with 0 neighbours exited with reason: no case clause matching {[{xmlstreamstart,<<"stream:stream">>,[{<<"xml:lang">>,"en"},{<<"xmlns">>,<<"jabber:client">>},{<<"xmlns:stream">>,<<"http://etherx.jabber.org/streams">>},{<<"id">>,"3411127855"},{<<"from">>,<<"localhost">>}]},{xmlstreamend,<<"stream:stream">>}],[{xmlel,<<"stream:error">>,[],[{xmlel,<<"host-unknown">>,[{<<"xmlns">>,<<"urn:ietf:params:xml:ns:xmpp-streams">>}],[]}]}]} in mod_bosh_socket:bosh_wrap/3 line 872 in gen_fsm:terminate/7 line 620
2014-11-07 12:25:38.367 [error] <0.433.0> Supervisor ejabberd_mod_bosh_socket_sup had child undefined started with {mod_bosh_socket,start_link,undefined} at <0.572.0> exit with reason no case clause matching {[{xmlstreamstart,<<"stream:stream">>,[{<<"xml:lang">>,"en"},{<<"xmlns">>,<<"jabber:client">>},{<<"xmlns:stream">>,<<"http://etherx.jabber.org/streams">>},{<<"id">>,"3411127855"},{<<"from">>,<<"localhost">>}]},{xmlstreamend,<<"stream:stream">>}],[{xmlel,<<"stream:error">>,[],[{xmlel,<<"host-unknown">>,[{<<"xmlns">>,<<"urn:ietf:params:xml:ns:xmpp-streams">>}],[]}]}]} in mod_bosh_socket:bosh_wrap/3 line 872 in context child_terminated

One thing to note is that I promise to open source the work that I done on this library in order to be compatible with mongoose :)

janjiss commented 9 years ago

P.S is full request response cycle:

Ruby-BOSH - SEND
[Fri Nov 07 12:01:27 2014]: <body rid="72882" xmlns="http://jabber.org/protocol/httpbind" xmpp:version="1.0" xmlns:xmpp="urn:xmpp:xbosh" wait="5" to="localhost" hold="1"/>
RESPONSE!!!!!!!!!!! <body maxpause='120' inactivity='30' xmlns:stream='http://etherx.jabber.org/streams' xmlns:xmpp='urn:xmpp:xbosh' xmlns='http://jabber.org/protocol/httpbind' xmpp:version='1.0' xmpp:restartlogic='true' sid='bb8f80c8826cd91b4492edbf2d5c1068cb73c743' accept='deflate,gzip' from='localhost' hold='1' requests='2' wait='5'><stream:features><mechanisms xmlns='urn:ietf:params:xml:ns:xmpp-sasl'><mechanism>PLAIN</mechanism><mechanism>DIGEST-MD5</mechanism><mechanism>SCRAM-SHA-1</mechanism></mechanisms><register xmlns='http://jabber.org/features/iq-register'/><amp xmlns='http://jabber.org/feature/amp'/><sm xmlns='urn:xmpp:sm:3'/></stream:features></body>
Ruby-BOSH - SEND
[Fri Nov 07 12:01:27 2014]: <body rid="72883" xmlns="http://jabber.org/protocol/httpbind" xmpp:version="1.0" xmlns:xmpp="urn:xmpp:xbosh" sid="bb8f80c8826cd91b4492edbf2d5c1068cb73c743"><auth xmlns="urn:ietf:params:xml:ns:xmpp-sasl" mechanism="PLAIN">Xzg1Ni1wdnc4eW13cnZkM3k0eWtqQGxvY2FsaG9zdABfODU2LXB2dzh5bXdydmQzeTR5a2oAZGFkYzg5MjQ1OGMxMmFhNzdhM2IzOTk4NzU3N2I5Y2M=</auth></body>
RESPONSE!!!!!!!!!!! <body xmlns='http://jabber.org/protocol/httpbind' sid='bb8f80c8826cd91b4492edbf2d5c1068cb73c743'><success xmlns='urn:ietf:params:xml:ns:xmpp-sasl'/></body>
Ruby-BOSH - SEND
[Fri Nov 07 12:01:27 2014]: <body rid="72884" xmlns="http://jabber.org/protocol/httpbind" xmpp:version="1.0" xmlns:xmpp="urn:xmpp:xbosh" sid="bb8f80c8826cd91b4492edbf2d5c1068cb73c743" xmpp:restart="true"/>
RESPONSE!!!!!!!!!!! <body xmlns='http://jabber.org/protocol/httpbind' sid='bb8f80c8826cd91b4492edbf2d5c1068cb73c743'/>
Ruby-BOSH - SEND
[Fri Nov 07 12:01:32 2014]: <body rid="72885" xmlns="http://jabber.org/protocol/httpbind" xmpp:version="1.0" xmlns:xmpp="urn:xmpp:xbosh" sid="bb8f80c8826cd91b4492edbf2d5c1068cb73c743"><iq id="bind_34635" type="set" xmlns="jabber:client"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind"><resource>bosh_727</resource></bind></iq></body>
<body rid="72885" xmlns="http://jabber.org/protocol/httpbind" xmpp:version="1.0" xmlns:xmpp="urn:xmpp:xbosh" sid="bb8f80c8826cd91b4492edbf2d5c1068cb73c743"><iq id="bind_34635" type="set" xmlns="jabber:client"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind"><resource>bosh_727</resource></bind></iq></body>
erszcz commented 9 years ago

Sorry, I'll be terse, but I'm short on time. Two problems (this is cut out of the "Pending" field from your log):

[{xmlstreamstart,<<"stream:stream">>,[{<<"xml:lang">>,"en"},{<<"xmlns">>,<<"jabber:client">>},{<<"xmlns:stream">>,<<"http://etherx.jabber.org/streams">>},{<<"id">>,"3411127855"},{<<"from">>,<<"localhost">>}]},
 {xmlel,<<"stream:error">>,[],[{xmlel,<<"host-unknown">>,[{<<"xmlns">>,<<"urn:ietf:params:xml:ns:xmpp-streams">>}],[]}]},
 {xmlstreamend,<<"stream:stream">>}]
  1. host-unknown - you send invalid XMPP domain (i.e. the part after @ but before / in JID), hence the error above. Compare with {hosts, [...]}. in you ejabberd.cfg in use by the server.
  2. You don't open enough (or fast enough?) HTTP requests to the server, so it can't return you the error - that's why the Pending list is not empty.
erszcz commented 9 years ago

Ahh, this sheds more light, but I guess your examples come from distinct runs of the test as BOSH session ids don't match (i.e. id on the client side vs id on the server side - in other words, these logs are about two distinct sessions). Could you show a consistent logs from start to the error (client and server side)?

janjiss commented 9 years ago

Full debug log:

2014-11-07 12:25:33.266 [debug] <0.571.0>@mod_bosh:init:163 New request
2014-11-07 12:25:33.266 [debug] <0.571.0>@mod_bosh:info:204 Parsed body: {xmlel,<<"body">>,[{<<"xmlns">>,<<"http://jabber.org/protocol/httpbind">>},{<<"xmlns:xmpp">>,<<"urn:xmpp:xbosh">>},{<<"rid">>,<<"45965">>},{<<"xmpp:version">>,<<"1.0">>},{<<"wait">>,<<"5">>},{<<"to">>,<<"localhost">>},{<<"hold">>,<<"1">>}],[]}
2014-11-07 12:25:33.267 [debug] <0.572.0>@mod_bosh_socket:init:181 mod_bosh_socket started
2014-11-07 12:25:33.267 [debug] <0.571.0>@mod_bosh:start_session:361 Created new session <<"6f60f745d2c5691dfa346c57f73fc5c8e720ea36">>
2014-11-07 12:25:33.278 [debug] <0.571.0>@mod_bosh:info:208 Sending (binary) to <<"6f60f745d2c5691dfa346c57f73fc5c8e720ea36">>: <<"<body maxpause='120' inactivity='30' xmlns:stream='http://etherx.jabber.org/streams' xmlns:xmpp='urn:xmpp:xbosh' xmlns='http://jabber.org/protocol/httpbind' xmpp:version='1.0' xmpp:restartlogic='true' sid='6f60f745d2c5691dfa346c57f73fc5c8e720ea36' accept='deflate,gzip' from='localhost' hold='1' requests='2' wait='5'><stream:features><mechanisms xmlns='urn:ietf:params:xml:ns:xmpp-sasl'><mechanism>PLAIN</mechanism><mechanism>DIGEST-MD5</mechanism><mechanism>SCRAM-SHA-1</mechanism></mechanisms><register xmlns='http://jabber.org/features/iq-register'/><amp xmlns='http://jabber.org/feature/amp'/><sm xmlns='urn:xmpp:sm:3'/></stream:features></body>">>
2014-11-07 12:25:33.298 [debug] <0.575.0>@mod_bosh:init:163 New request
2014-11-07 12:25:33.298 [debug] <0.575.0>@mod_bosh:info:204 Parsed body: {xmlel,<<"body">>,[{<<"xmlns">>,<<"http://jabber.org/protocol/httpbind">>},{<<"xmlns:xmpp">>,<<"urn:xmpp:xbosh">>},{<<"rid">>,<<"45966">>},{<<"xmpp:version">>,<<"1.0">>},{<<"sid">>,<<"6f60f745d2c5691dfa346c57f73fc5c8e720ea36">>}],[{xmlel,<<"auth">>,[{<<"xmlns">>,<<"urn:ietf:params:xml:ns:xmpp-sasl">>},{<<"mechanism">>,<<"PLAIN">>}],[{xmlcdata,<<"Xzg1Ni1wdnc4eW13cnZkM3k0eWtqQGxvY2FsaG9zdABfODU2LXB2dzh5bXdydmQzeTR5a2oAZGFkYzg5MjQ1OGMxMmFhNzdhM2IzOTk4NzU3N2I5Y2M=">>}]}]}
2014-11-07 12:25:33.299 [debug] <0.573.0>@ejabberd_auth_http:make_req:243 Making request 'check_password' for user _856-pvw8ymwrvd3y4ykj@localhost...
2014-11-07 12:25:33.327 [debug] <0.573.0>@ejabberd_auth_http:make_req:251 Request result: 200: <<"true">>
2014-11-07 12:25:33.327 [info] <0.573.0>@ejabberd_c2s:wait_for_feature_request:704 ({bosh_socket,<<54,102,54,48,102,55,52,53,100,50,99,53,54,57,49,100,102,97,51,52,54,99,53,55,102,55,51,102,99,53,99,56,101,55,50,48,101,97,51,54>>,<0.572.0>,{{127,0,0,1},55889}}) Accepted authentication for _856-pvw8ymwrvd3y4ykj by ejabberd_auth_http
2014-11-07 12:25:33.327 [debug] <0.572.0>@mod_bosh_socket:handle_info:371 Stream reset by c2s
2014-11-07 12:25:33.327 [debug] <0.575.0>@mod_bosh:info:208 Sending (binary) to <<"6f60f745d2c5691dfa346c57f73fc5c8e720ea36">>: <<"<body xmlns='http://jabber.org/protocol/httpbind' sid='6f60f745d2c5691dfa346c57f73fc5c8e720ea36'><success xmlns='urn:ietf:params:xml:ns:xmpp-sasl'/></body>">>
2014-11-07 12:25:33.344 [debug] <0.576.0>@mod_bosh:init:163 New request
2014-11-07 12:25:33.344 [debug] <0.576.0>@mod_bosh:info:204 Parsed body: {xmlel,<<"body">>,[{<<"xmlns">>,<<"http://jabber.org/protocol/httpbind">>},{<<"xmlns:xmpp">>,<<"urn:xmpp:xbosh">>},{<<"rid">>,<<"45967">>},{<<"xmpp:version">>,<<"1.0">>},{<<"sid">>,<<"6f60f745d2c5691dfa346c57f73fc5c8e720ea36">>},{<<"xmpp:restart">>,<<"true">>}],[]}
2014-11-07 12:25:33.355 [debug] <0.572.0>@mod_bosh_socket:closing:230 Unhandled event in 'normal' state: acc_off
2014-11-07 12:25:38.347 [info] <0.572.0>@mod_bosh_socket:handle_info:382 'wait' limit reached for <0.576.0>
2014-11-07 12:25:38.347 [debug] <0.576.0>@mod_bosh:info:208 Sending (binary) to <<"6f60f745d2c5691dfa346c57f73fc5c8e720ea36">>: <<"<body xmlns='http://jabber.org/protocol/httpbind' sid='6f60f745d2c5691dfa346c57f73fc5c8e720ea36'/>">>
2014-11-07 12:25:38.366 [debug] <0.578.0>@mod_bosh:init:163 New request
2014-11-07 12:25:38.366 [debug] <0.578.0>@mod_bosh:info:204 Parsed body: {xmlel,<<"body">>,[{<<"xmlns">>,<<"http://jabber.org/protocol/httpbind">>},{<<"xmlns:xmpp">>,<<"urn:xmpp:xbosh">>},{<<"rid">>,<<"45968">>},{<<"xmpp:version">>,<<"1.0">>},{<<"sid">>,<<"6f60f745d2c5691dfa346c57f73fc5c8e720ea36">>}],[{xmlel,<<"iq">>,[{<<"xmlns">>,<<"jabber:client">>},{<<"id">>,<<"bind_99074">>},{<<"type">>,<<"set">>}],[{xmlel,<<"bind">>,[{<<"xmlns">>,<<"urn:ietf:params:xml:ns:xmpp-bind">>}],[{xmlel,<<"resource">>,[],[{xmlcdata,<<"bosh_226">>}]}]}]}]}
2014-11-07 12:25:38.366 [debug] <0.572.0>@mod_bosh_socket:terminate:400 Closing session <<"6f60f745d2c5691dfa346c57f73fc5c8e720ea36">> in 'closing' state. Handlers: [] Pending: [{xmlstreamstart,<<"stream:stream">>,[{<<"xml:lang">>,"en"},{<<"xmlns">>,<<"jabber:client">>},{<<"xmlns:stream">>,<<"http://etherx.jabber.org/streams">>},{<<"id">>,"3411127855"},{<<"from">>,<<"localhost">>}]},{xmlel,<<"stream:error">>,[],[{xmlel,<<"host-unknown">>,[{<<"xmlns">>,<<"urn:ietf:params:xml:ns:xmpp-streams">>}],[]}]},{xmlstreamend,<<"stream:stream">>}]
2014-11-07 12:25:38.367 [error] <0.572.0> gen_fsm <0.572.0> in state closing terminated with reason: no case clause matching {[{xmlstreamstart,<<"stream:stream">>,[{<<"xml:lang">>,"en"},{<<"xmlns">>,<<"jabber:client">>},{<<"xmlns:stream">>,<<"http://etherx.jabber.org/streams">>},{<<"id">>,"3411127855"},{<<"from">>,<<"localhost">>}]},{xmlstreamend,<<"stream:stream">>}],[{xmlel,<<"stream:error">>,[],[{xmlel,<<"host-unknown">>,[{<<"xmlns">>,<<"urn:ietf:params:xml:ns:xmpp-streams">>}],[]}]}]} in mod_bosh_socket:bosh_wrap/3 line 872
2014-11-07 12:25:38.367 [error] <0.572.0> CRASH REPORT Process <0.572.0> with 0 neighbours exited with reason: no case clause matching {[{xmlstreamstart,<<"stream:stream">>,[{<<"xml:lang">>,"en"},{<<"xmlns">>,<<"jabber:client">>},{<<"xmlns:stream">>,<<"http://etherx.jabber.org/streams">>},{<<"id">>,"3411127855"},{<<"from">>,<<"localhost">>}]},{xmlstreamend,<<"stream:stream">>}],[{xmlel,<<"stream:error">>,[],[{xmlel,<<"host-unknown">>,[{<<"xmlns">>,<<"urn:ietf:params:xml:ns:xmpp-streams">>}],[]}]}]} in mod_bosh_socket:bosh_wrap/3 line 872 in gen_fsm:terminate/7 line 620
2014-11-07 12:25:38.367 [error] <0.433.0> Supervisor ejabberd_mod_bosh_socket_sup had child undefined started with {mod_bosh_socket,start_link,undefined} at <0.572.0> exit with reason no case clause matching {[{xmlstreamstart,<<"stream:stream">>,[{<<"xml:lang">>,"en"},{<<"xmlns">>,<<"jabber:client">>},{<<"xmlns:stream">>,<<"http://etherx.jabber.org/streams">>},{<<"id">>,"3411127855"},{<<"from">>,<<"localhost">>}]},{xmlstreamend,<<"stream:stream">>}],[{xmlel,<<"stream:error">>,[],[{xmlel,<<"host-unknown">>,[{<<"xmlns">>,<<"urn:ietf:params:xml:ns:xmpp-streams">>}],[]}]}]} in mod_bosh_socket:bosh_wrap/3 line 872 in context child_terminated
janjiss commented 9 years ago 
@mod_bosh_socket:handle_info:382 'wait' limit reached for

When pasted here, it all started to make sense now. So probably I have a problem with execution time. Is this the case?

erszcz commented 9 years ago

I'm not sure. I'm more puzzled by

2014-11-07 12:25:33.355 [debug] <0.572.0>@mod_bosh_socket:closing:230 Unhandled event in 'normal' state: acc_off

but why would 572 already be @mod_bosh_socket:closing (i.e. in closing state)? BTW, the log message is incorrect, it should state Unhandled event in 'closing' state: acc_off . Still, I can't dive into it at the moment, sorry.

janjiss commented 9 years ago

@lavrin One more thing, I am using http_auth for external authentication. It works if I use internal.

erszcz commented 9 years ago

Whoah, that's even more interesting. I guess @fenek might know something about that.

fenek commented 9 years ago

@fenek is not sure about this one. Auth backends are stateless (the only state auth_http has is the HTTP client process)... Can you please paste the same slice of debug logs when using auth_internal?

janjiss commented 9 years ago

OK guys, so this is the log from mongoose:

(mongooseim@localhost)1> 2014-11-12 11:05:56.562 [debug] <0.519.0>@mod_bosh:init:163 New request
2014-11-12 11:05:56.568 [debug] <0.519.0>@mod_bosh:info:204 Parsed body: {xmlel,<<"body">>,[{<<"xmlns">>,<<"http://jabber.org/protocol/httpbind">>},{<<"content">>,<<"text/xml; charset=utf-8">>},{<<"hold">>,<<"1">>},{<<"rid">>,<<"1049">>},{<<"route">>,<<"xmpp:localhost:5222">>},{<<"secure">>,<<"true">>},{<<"to">>,<<"localhost">>},{<<"wait">>,<<"20">>}],[]}
2014-11-12 11:05:56.578 [debug] <0.523.0>@mod_bosh_socket:init:181 mod_bosh_socket started
2014-11-12 11:05:56.578 [debug] <0.519.0>@mod_bosh:start_session:361 Created new session <<"65d3a627e905443a794fb74bdf0f1d7010c17b96">>
2014-11-12 11:05:56.589 [debug] <0.519.0>@mod_bosh:info:208 Sending (binary) to <<"65d3a627e905443a794fb74bdf0f1d7010c17b96">>: <<"<body maxpause='120' inactivity='30' xmlns:stream='http://etherx.jabber.org/streams' xmlns:xmpp='urn:xmpp:xbosh' xmlns='http://jabber.org/protocol/httpbind' xmpp:version='1.0' xmpp:restartlogic='true' sid='65d3a627e905443a794fb74bdf0f1d7010c17b96' accept='deflate,gzip' from='localhost' hold='1' requests='2' wait='20'><stream:features><mechanisms xmlns='urn:ietf:params:xml:ns:xmpp-sasl'><mechanism>PLAIN</mechanism><mechanism>DIGEST-MD5</mechanism><mechanism>SCRAM-SHA-1</mechanism></mechanisms><register xmlns='http://jabber.org/features/iq-register'/><amp xmlns='http://jabber.org/feature/amp'/><sm xmlns='urn:xmpp:sm:3'/></stream:features></body>">>
2014-11-12 11:05:56.593 [debug] <0.526.0>@mod_bosh:init:163 New request
2014-11-12 11:05:56.594 [debug] <0.526.0>@mod_bosh:info:204 Parsed body: {xmlel,<<"body">>,[{<<"xmlns">>,<<"http://jabber.org/protocol/httpbind">>},{<<"rid">>,<<"1050">>},{<<"sid">>,<<"65d3a627e905443a794fb74bdf0f1d7010c17b96">>}],[{xmlel,<<"iq">>,[{<<"id">>,<<"2372">>},{<<"to">>,<<"localhost">>},{<<"type">>,<<"set">>}],[{xmlel,<<"query">>,[{<<"xmlns">>,<<"jabber:iq:register">>}],[{xmlel,<<"username">>,[],[{xmlcdata,<<"_rc_zx84bfc-1qb3texwj">>}]},{xmlel,<<"password">>,[],[{xmlcdata,<<"mypass">>}]}]}]}]}
2014-11-12 11:05:56.594 [debug] <0.526.0>@mod_bosh:info:208 Sending (binary) to <<"65d3a627e905443a794fb74bdf0f1d7010c17b96">>: <<"<body xmlns='http://jabber.org/protocol/httpbind' sid='65d3a627e905443a794fb74bdf0f1d7010c17b96'><iq type='result' id='2372' from='localhost' xmlns='jabber:client'><query xmlns='jabber:iq:register'><username>_rc_zx84bfc-1qb3texwj</username><password>mypass</password></query></iq></body>">>
2014-11-12 11:05:56.703 [debug] <0.527.0>@mod_bosh:init:163 New request
2014-11-12 11:05:56.703 [debug] <0.527.0>@mod_bosh:info:204 Parsed body: {xmlel,<<"body">>,[{<<"xmlns">>,<<"http://jabber.org/protocol/httpbind">>},{<<"rid">>,<<"1051">>},{<<"sid">>,<<"65d3a627e905443a794fb74bdf0f1d7010c17b96">>}],[{xmlel,<<"auth">>,[{<<"xmlns">>,<<"urn:ietf:params:xml:ns:xmpp-sasl">>},{<<"mechanism">>,<<"DIGEST-MD5">>}],[]}]}
2014-11-12 11:05:56.703 [debug] <0.527.0>@mod_bosh:info:208 Sending (binary) to <<"65d3a627e905443a794fb74bdf0f1d7010c17b96">>: <<"<body xmlns='http://jabber.org/protocol/httpbind' sid='65d3a627e905443a794fb74bdf0f1d7010c17b96'><challenge xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>bm9uY2U9Ijc1OTAzNTQ0MiIscW9wPSJhdXRoIixjaGFyc2V0PXV0Zi04LGFsZ29yaXRobT1tZDUtc2Vzcw==</challenge></body>">>
2014-11-12 11:05:56.811 [debug] <0.528.0>@mod_bosh:init:163 New request
2014-11-12 11:05:56.811 [debug] <0.528.0>@mod_bosh:info:204 Parsed body: {xmlel,<<"body">>,[{<<"xmlns">>,<<"http://jabber.org/protocol/httpbind">>},{<<"rid">>,<<"1052">>},{<<"sid">>,<<"65d3a627e905443a794fb74bdf0f1d7010c17b96">>}],[{xmlel,<<"response">>,[{<<"xmlns">>,<<"urn:ietf:params:xml:ns:xmpp-sasl">>}],[{xmlcdata,<<"bm9uY2U9Ijc1OTAzNTQ0MiIsY2hhcnNldD11dGYtOCx1c2VybmFtZT0iX3JjX3p4ODRiZmMtMXFiM3RleHdqIixyZWFsbT0ibG9jYWxob3N0Iixjbm9uY2U9IjdhZjk0ZmIyMGE3NmY1NzgzNDc0ZGM5ZjJhYmZkYTFjIixuYz0wMDAwMDAwMSxxb3A9YXV0aCxkaWdlc3QtdXJpPSJ4bXBwL2xvY2FsaG9zdCIscmVzcG9uc2U9M2I1MDc3YTIzYTllZWZiY2ZiMDIwNzg2YTZjMjhlZGQ=">>}]}]}
2014-11-12 11:05:56.812 [debug] <0.528.0>@mod_bosh:info:208 Sending (binary) to <<"65d3a627e905443a794fb74bdf0f1d7010c17b96">>: <<"<body xmlns='http://jabber.org/protocol/httpbind' sid='65d3a627e905443a794fb74bdf0f1d7010c17b96'><challenge xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>cnNwYXV0aD1hYWQyN2ExODg4ZThlZmZlNmQ2NjkyMmFhZWUyZWFkNw==</challenge></body>">>
2014-11-12 11:05:56.915 [debug] <0.529.0>@mod_bosh:init:163 New request
2014-11-12 11:05:56.916 [debug] <0.529.0>@mod_bosh:info:204 Parsed body: {xmlel,<<"body">>,[{<<"xmlns">>,<<"http://jabber.org/protocol/httpbind">>},{<<"rid">>,<<"1053">>},{<<"sid">>,<<"65d3a627e905443a794fb74bdf0f1d7010c17b96">>}],[{xmlel,<<"response">>,[{<<"xmlns">>,<<"urn:ietf:params:xml:ns:xmpp-sasl">>}],[]}]}
2014-11-12 11:05:56.916 [debug] <0.523.0>@mod_bosh_socket:handle_info:371 Stream reset by c2s
2014-11-12 11:05:56.916 [info] <0.524.0>@ejabberd_c2s:wait_for_sasl_response:845 ({bosh_socket,<<54,53,100,51,97,54,50,55,101,57,48,53,52,52,51,97,55,57,52,102,98,55,52,98,100,102,48,102,49,100,55,48,49,48,99,49,55,98,57,54>>,<0.523.0>,{{127,0,0,1},52124}}) Accepted authentication for _rc_zx84bfc-1qb3texwj by ejabberd_auth_internal
2014-11-12 11:05:56.916 [debug] <0.529.0>@mod_bosh:info:208 Sending (binary) to <<"65d3a627e905443a794fb74bdf0f1d7010c17b96">>: <<"<body xmlns='http://jabber.org/protocol/httpbind' sid='65d3a627e905443a794fb74bdf0f1d7010c17b96'><success xmlns='urn:ietf:params:xml:ns:xmpp-sasl'/></body>">>
2014-11-12 11:05:57.024 [debug] <0.530.0>@mod_bosh:init:163 New request
2014-11-12 11:05:57.024 [debug] <0.530.0>@mod_bosh:info:204 Parsed body: {xmlel,<<"body">>,[{<<"xmlns">>,<<"http://jabber.org/protocol/httpbind">>},{<<"xmlns:xmpp">>,<<"urn:xmpp:xbosh">>},{<<"rid">>,<<"1054">>},{<<"sid">>,<<"65d3a627e905443a794fb74bdf0f1d7010c17b96">>},{<<"xml:lang">>,<<"en">>},{<<"xmpp:restart">>,<<"true">>}],[]}
2014-11-12 11:05:57.036 [debug] <0.523.0>@mod_bosh_socket:closing:230 Unhandled event in 'normal' state: acc_off
2014-11-12 11:06:06.950 [debug] <0.319.0>@shaper_srv:handle_info:133 Deleted old shapers
2014-11-12 11:06:06.950 [debug] <0.320.0>@shaper_srv:handle_info:133 Deleted old shapers
2014-11-12 11:06:06.950 [debug] <0.321.0>@shaper_srv:handle_info:133 Deleted old shapers
2014-11-12 11:06:06.950 [debug] <0.322.0>@shaper_srv:handle_info:133 Deleted old shapers
2014-11-12 11:06:06.950 [debug] <0.323.0>@shaper_srv:handle_info:133 Deleted old shapers
2014-11-12 11:06:06.950 [debug] <0.324.0>@shaper_srv:handle_info:133 Deleted old shapers
2014-11-12 11:06:06.950 [debug] <0.326.0>@shaper_srv:handle_info:133 Deleted old shapers
2014-11-12 11:06:06.950 [debug] <0.325.0>@shaper_srv:handle_info:133 Deleted old shapers
2014-11-12 11:06:06.950 [debug] <0.327.0>@shaper_srv:handle_info:133 Deleted old shapers
2014-11-12 11:06:06.950 [debug] <0.328.0>@shaper_srv:handle_info:133 Deleted old shapers
2014-11-12 11:06:17.029 [info] <0.523.0>@mod_bosh_socket:handle_info:382 'wait' limit reached for <0.530.0>
2014-11-12 11:06:17.029 [debug] <0.530.0>@mod_bosh:info:208 Sending (binary) to <<"65d3a627e905443a794fb74bdf0f1d7010c17b96">>: <<"<body xmlns='http://jabber.org/protocol/httpbind' sid='65d3a627e905443a794fb74bdf0f1d7010c17b96'/>">>

@fenek I am sorry, I think the HTTP auth had nothing to do with this. I tried to use both external and internal auth and this was the result. In this log I open a connection, register user and then try to authenticate with this user, and system stops at this line and my lib just hangs there and waits for response:

2014-11-12 11:05:57.036 [debug] <0.523.0>@mod_bosh_socket:closing:230 Unhandled event in 'normal' state: acc_off

Also, I found more up to date library for Ruby, so this eliminates the problem with the lib itself.

What seems interesting, that after the wait limit is reached, it tries to send binary to already dead connection.

janjiss commented 9 years ago

@lavrin Maybe we can have a call with screen share in order to solve this issue?

erszcz commented 9 years ago

Sorry, I can't spend more time on this issue right now.

erszcz commented 9 years ago

@janjiss, is your fork of the library public? I'd like to try debugging the problem locally.

janjiss commented 9 years ago

@lavrin As I said, I tried different library, which is more up to date, so I do not think this is the issue with library. This problem happens when I issue restart. Library I used this time: https://github.com/xmpp4r/xmpp4r

erszcz commented 9 years ago

I don't imply it's an issue with the library. I just want the shortest sure path to recreate the problem on my dev box. All in all, we have a test suite which doesn't uncover the problem you run into, so some puzzles don't match in your scenario with what we usually do. Maybe you could provide a minimal snippet to recreate the problem using this new lib? Thanks for reporting the problem.

janjiss commented 9 years ago

@lavrin Shortest way to reproduce the problem with internal auth would be to do it like this:

require "xmpp4r"
require "xmpp4r/httpbinding"
jid = "my_jid@localhost"
client = Jabber::HTTPBinding::Client.new(jid)
client.connect("http://localhost:5280/http-bind", "localhost")
client.register("mypassword")
client.auth("mypassword")

launch it with command:

ruby xmpp_auth.rb

P.S After you do it once, you should remove client.register("mypassword") part, since there will be user allready :)

erszcz commented 9 years ago

@janjiss, the referenced branch contains the fix. It should be shortly merged into master.

janjiss commented 9 years ago

@lavrin Confirming that this fixed issue for me. Works like a charm. Thank you, I really appreciate you looking in to this.