ejabberd BOSH takes too many minutes in HTTP pre-bind

Question

The context:

I'm trying to generate a session from my back-end to attach to it from my front-end. In the process, I'm sending the request to ejabberd, to the mod_http_bind module listening on the port 5280, as is explained in metajack.im post.

Session id requests are sent using this script.

I'm using external authentication and is working well, in a normal time, when connecting directly through XMPP or WebAdmin.

The problem:

It's generating the session id right BUT it's taking around 1-3 minutes. After this time my Bosh chat client through a timeout. Beside this, it's too much time for a simple session id.

Any suggestion??

Extra info:

Here is my ejabberd logs:

ejabberd-log

2015-12-14 15:52:34.655 [info] <0.490.0>@ejabberd_listener:accept:299 (#Port<0.3971>) Accepted connection 127.0.0.1:49840 -> 127.0.0.1:5280
2015-12-14 15:52:34.655 [info] <0.713.0>@ejabberd_http:init:157 started: {gen_tcp,#Port<0.3971>}
2015-12-14 15:53:43.187 [info] <0.490.0>@ejabberd_listener:accept:299 (#Port<0.3972>) Accepted connection 127.0.0.1:49855 -> 127.0.0.1:5280
2015-12-14 15:53:43.187 [info] <0.715.0>@ejabberd_http:init:157 started: {gen_tcp,#Port<0.3972>}

error.log

--empty--

crash.log

--empty--

Ejabberd version:

15.11

ejabberd.log with log_level at debug

2015-12-14 16:20:19.170 [info] <0.1240.0>@ejabberd_listener:accept:299 (#Port<0.7839>) Accepted connection 127.0.0.1:50027 -> 127.0.0.1:5280
2015-12-14 16:20:19.170 [debug] <0.1241.0>@ejabberd_http:init:153 S: [{[<<"register">>],mod_register_web},{[<<"admin">>],ejabberd_web_admin},{[<<"http-bind">>],mod_http_bind}]
2015-12-14 16:20:19.170 [info] <0.1241.0>@ejabberd_http:init:157 started: {gen_tcp,#Port<0.7839>}
2015-12-14 16:20:19.170 [debug] <0.1241.0>@ejabberd_http:process_header:280 (#Port<0.7839>) http query: 'POST' <<"/http-bind">>
2015-12-14 16:20:19.170 [debug] <0.1241.0>@ejabberd_http:extract_path_query:392 client data: <<"<body xmlns='http://jabber.org/protocol/httpbind' content='text/xml; charset=utf-8' to='chatdomain' window='5' xml:lang='en' rid='1598394' hold='1' wait='70'/>">>
2015-12-14 16:20:19.170 [debug] <0.1241.0>@ejabberd_http:process:350 [<<"http-bind">>] matches [<<"http-bind">>]
2015-12-14 16:20:19.170 [debug] <0.1241.0>@mod_http_bind:process:68 Incoming data: <body xmlns='http://jabber.org/protocol/httpbind' content='text/xml; charset=utf-8' to='chatdomain' window='5' xml:lang='en' rid='1598394' hold='1' wait='70'/>
2015-12-14 16:20:19.171 [debug] <0.1241.0>@ejabberd_http_bind:parse_request:1114 --- incoming data --- 
<body xmlns='http://jabber.org/protocol/httpbind' content='text/xml; charset=utf-8' to='chatdomain' window='5' xml:lang='en' rid='1598394' hold='1' wait='70'/>
 --- END --- 
2015-12-14 16:20:19.171 [debug] <0.1241.0>@ejabberd_http_bind:start:154 Starting session
2015-12-14 16:20:19.176 [debug] <0.1242.0>@ejabberd_http_bind:init:339 started: {<<"92c4475848d8b8f10b4dbe1a66980c385f46ac00">>,<<>>,{{127,0,0,1},50027}}
2015-12-14 16:20:19.176 [debug] <0.1241.0>@ejabberd_http_bind:handle_session_start:282 got pid: <0.1242.0>
2015-12-14 16:20:19.176 [debug] <0.1241.0>@ejabberd_http_bind:handle_session_start:321 Create session: <<"92c4475848d8b8f10b4dbe1a66980c385f46ac00">>
2015-12-14 16:20:19.176 [debug] <0.1241.0>@ejabberd_http_bind:http_put:775 Looking for session: <<"92c4475848d8b8f10b4dbe1a66980c385f46ac00">>
2015-12-14 16:20:19.176 [debug] <0.1242.0>@ejabberd_http_bind:handle_sync_event:442 New request: {http_put,1598394,[{<<"xmlns">>,<<"http://jabber.org/protocol/httpbind">>},{<<"content">>,<<"text/xml; charset=utf-8">>},{<<"to">>,<<"chatdomain">>},{<<"window">>,<<"5">>},{<<"xml:lang">>,<<"en">>},{<<"rid">>,<<"1598394">>},{<<"hold">>,<<"1">>},{<<"wait">>,<<"70">>}],[],155,1,{<<"chatdomain">>,<<>>},{{127,0,0,1},50027}}
2015-12-14 16:20:19.176 [debug] <0.1242.0>@ejabberd_http_bind:handle_http_put_event:558 New request: {http_put,1598394,[{<<"xmlns">>,<<"http://jabber.org/protocol/httpbind">>},{<<"content">>,<<"text/xml; charset=utf-8">>},{<<"to">>,<<"chatdomain">>},{<<"window">>,<<"5">>},{<<"xml:lang">>,<<"en">>},{<<"rid">>,<<"1598394">>},{<<"hold">>,<<"1">>},{<<"wait">>,<<"70">>}],[],155,1,{<<"chatdomain">>,<<>>},{{127,0,0,1},50027}}
2015-12-14 16:20:19.176 [debug] <0.1242.0>@ejabberd_http_bind:process_http_put:591 Actually processing request: {http_put,1598394,[{<<"xmlns">>,<<"http://jabber.org/protocol/httpbind">>},{<<"content">>,<<"text/xml; charset=utf-8">>},{<<"to">>,<<"chatdomain">>},{<<"window">>,<<"5">>},{<<"xml:lang">>,<<"en">>},{<<"rid">>,<<"1598394">>},{<<"hold">>,<<"1">>},{<<"wait">>,<<"70">>}],[],155,1,{<<"chatdomain">>,<<>>},{{127,0,0,1},50027}}
2015-12-14 16:20:19.176 [debug] <0.1242.0>@ejabberd_http_bind:process_http_put:642  -- SaveKey: 
2015-12-14 16:20:19.176 [debug] <0.1242.0>@ejabberd_http_bind:process_http_put:654 reqlist: [{hbr,1598394,<<>>,[]}]
2015-12-14 16:20:19.176 [debug] <0.1242.0>@ejabberd_http_bind:process_http_put:700 really sending now: []
2015-12-14 16:20:19.278 [debug] <0.1241.0>@ejabberd_http_bind:prepare_response:900 OutPacket: [{xmlstreamstart,<<"stream:stream">>,[{<<"xml:lang">>,<<"en">>},{<<"xmlns">>,<<"jabber:client">>},{<<"xmlns:stream">>,<<"http://etherx.jabber.org/streams">>},{<<"id">>,<<"108440446">>},{<<"from">>,<<"chatdomain">>}]}]
2015-12-14 16:20:19.279 [info] <0.1240.0>@ejabberd_listener:accept:299 (#Port<0.7846>) Accepted connection 127.0.0.1:50028 -> 127.0.0.1:5280
2015-12-14 16:20:19.279 [debug] <0.1244.0>@ejabberd_http:init:153 S: [{[<<"register">>],mod_register_web},{[<<"admin">>],ejabberd_web_admin},{[<<"http-bind">>],mod_http_bind}]
2015-12-14 16:20:19.279 [info] <0.1244.0>@ejabberd_http:init:157 started: {gen_tcp,#Port<0.7846>}
2015-12-14 16:20:19.279 [debug] <0.1244.0>@ejabberd_http:process_header:280 (#Port<0.7846>) http query: 'POST' <<"/http-bind">>
2015-12-14 16:20:19.279 [debug] <0.1244.0>@ejabberd_http:extract_path_query:392 client data: <<"<body xmlns='http://jabber.org/protocol/httpbind' content='text/xml; charset=utf-8' rid='1598395' xml:lang='en' sid='92c4475848d8b8f10b4dbe1a66980c385f46ac00'><auth xmlns='urn:ietf:params:xml:ns:xmpp-sasl' mechanism='PLAIN'>AGFkbWluADEyMzQ=\n</auth></body>">>
2015-12-14 16:20:19.279 [debug] <0.1244.0>@ejabberd_http:process:350 [<<"http-bind">>] matches [<<"http-bind">>]
2015-12-14 16:20:19.279 [debug] <0.1244.0>@mod_http_bind:process:68 Incoming data: <body xmlns='http://jabber.org/protocol/httpbind' content='text/xml; charset=utf-8' rid='1598395' xml:lang='en' sid='92c4475848d8b8f10b4dbe1a66980c385f46ac00'><auth xmlns='urn:ietf:params:xml:ns:xmpp-sasl' mechanism='PLAIN'>AGFkbWluADEyMzQ=
</auth></body>
2015-12-14 16:20:19.279 [debug] <0.1244.0>@ejabberd_http_bind:parse_request:1114 --- incoming data --- 
<body xmlns='http://jabber.org/protocol/httpbind' content='text/xml; charset=utf-8' rid='1598395' xml:lang='en' sid='92c4475848d8b8f10b4dbe1a66980c385f46ac00'><auth xmlns='urn:ietf:params:xml:ns:xmpp-sasl' mechanism='PLAIN'>AGFkbWluADEyMzQ=
</auth></body>
 --- END --- 
2015-12-14 16:20:19.279 [debug] <0.1244.0>@ejabberd_http_bind:http_put:775 Looking for session: <<"92c4475848d8b8f10b4dbe1a66980c385f46ac00">>
2015-12-14 16:20:19.279 [debug] <0.1242.0>@ejabberd_http_bind:handle_sync_event:442 New request: {http_put,1598395,[{<<"xmlns">>,<<"http://jabber.org/protocol/httpbind">>},{<<"content">>,<<"text/xml; charset=utf-8">>},{<<"rid">>,<<"1598395">>},{<<"xml:lang">>,<<"en">>},{<<"sid">>,<<"92c4475848d8b8f10b4dbe1a66980c385f46ac00">>}],[{xmlel,<<"auth">>,[{<<"xmlns">>,<<"urn:ietf:params:xml:ns:xmpp-sasl">>},{<<"mechanism">>,<<"PLAIN">>}],[{xmlcdata,<<"AGFkbWluADEyMzQ=\n">>}]}],255,1,<<>>,{{127,0,0,1},50028}}
2015-12-14 16:20:19.280 [debug] <0.1242.0>@ejabberd_http_bind:handle_http_put_event:558 New request: {http_put,1598395,[{<<"xmlns">>,<<"http://jabber.org/protocol/httpbind">>},{<<"content">>,<<"text/xml; charset=utf-8">>},{<<"rid">>,<<"1598395">>},{<<"xml:lang">>,<<"en">>},{<<"sid">>,<<"92c4475848d8b8f10b4dbe1a66980c385f46ac00">>}],[{xmlel,<<"auth">>,[{<<"xmlns">>,<<"urn:ietf:params:xml:ns:xmpp-sasl">>},{<<"mechanism">>,<<"PLAIN">>}],[{xmlcdata,<<"AGFkbWluADEyMzQ=\n">>}]}],255,1,<<>>,{{127,0,0,1},50028}}
2015-12-14 16:20:19.280 [debug] <0.1242.0>@ejabberd_http_bind:rid_allow:852 Previous rid / New rid: 1598394/1598395
2015-12-14 16:20:19.280 [debug] <0.1242.0>@ejabberd_http_bind:process_http_put:591 Actually processing request: {http_put,1598395,[{<<"xmlns">>,<<"http://jabber.org/protocol/httpbind">>},{<<"content">>,<<"text/xml; charset=utf-8">>},{<<"rid">>,<<"1598395">>},{<<"xml:lang">>,<<"en">>},{<<"sid">>,<<"92c4475848d8b8f10b4dbe1a66980c385f46ac00">>}],[{xmlel,<<"auth">>,[{<<"xmlns">>,<<"urn:ietf:params:xml:ns:xmpp-sasl">>},{<<"mechanism">>,<<"PLAIN">>}],[{xmlcdata,<<"AGFkbWluADEyMzQ=\n">>}]}],255,1,<<>>,{{127,0,0,1},50028}}
2015-12-14 16:20:19.280 [debug] <0.1242.0>@ejabberd_http_bind:process_http_put:642  -- SaveKey: 
2015-12-14 16:20:19.280 [debug] <0.1242.0>@ejabberd_http_bind:process_http_put:654 reqlist: [{hbr,1598395,<<>>,[]},{hbr,1598394,<<>>,[{xmlstreamstart,<<"stream:stream">>,[{<<"xml:lang">>,<<"en">>},{<<"xmlns">>,<<"jabber:client">>},{<<"xmlns:stream">>,<<"http://etherx.jabber.org/streams">>},{<<"id">>,<<"108440446">>},{<<"from">>,<<"chatdomain">>}]}]}]
2015-12-14 16:20:19.280 [debug] <0.1242.0>@ejabberd_http_bind:process_http_put:700 really sending now: [{xmlel,<<"auth">>,[{<<"xmlns">>,<<"urn:ietf:params:xml:ns:xmpp-sasl">>},{<<"mechanism">>,<<"PLAIN">>}],[{xmlcdata,<<"AGFkbWluADEyMzQ=\n">>}]}]
^[OF2015-12-14 16:21:29.387 [info] <0.1240.0>@ejabberd_listener:accept:299 (#Port<0.7847>) Accepted connection 127.0.0.1:50030 -> 127.0.0.1:5280
2015-12-14 16:21:29.388 [debug] <0.1245.0>@ejabberd_http:init:153 S: [{[<<"register">>],mod_register_web},{[<<"admin">>],ejabberd_web_admin},{[<<"http-bind">>],mod_http_bind}]
2015-12-14 16:21:29.388 [info] <0.1245.0>@ejabberd_http:init:157 started: {gen_tcp,#Port<0.7847>}
2015-12-14 16:21:29.388 [debug] <0.1245.0>@ejabberd_http:process_header:280 (#Port<0.7847>) http query: 'POST' <<"/http-bind">>
2015-12-14 16:21:29.388 [debug] <0.1245.0>@ejabberd_http:extract_path_query:392 client data: <<"<body xmlns='http://jabber.org/protocol/httpbind' content='text/xml; charset=utf-8' rid='1598396' xml:lang='en' sid='92c4475848d8b8f10b4dbe1a66980c385f46ac00'/>">>
2015-12-14 16:21:29.388 [debug] <0.1245.0>@ejabberd_http:process:350 [<<"http-bind">>] matches [<<"http-bind">>]
2015-12-14 16:21:29.388 [debug] <0.1245.0>@mod_http_bind:process:68 Incoming data: <body xmlns='http://jabber.org/protocol/httpbind' content='text/xml; charset=utf-8' rid='1598396' xml:lang='en' sid='92c4475848d8b8f10b4dbe1a66980c385f46ac00'/>
2015-12-14 16:21:29.388 [debug] <0.1245.0>@ejabberd_http_bind:parse_request:1114 --- incoming data --- 
<body xmlns='http://jabber.org/protocol/httpbind' content='text/xml; charset=utf-8' rid='1598396' xml:lang='en' sid='92c4475848d8b8f10b4dbe1a66980c385f46ac00'/>
 --- END --- 
2015-12-14 16:21:29.388 [debug] <0.1245.0>@ejabberd_http_bind:http_put:775 Looking for session: <<"92c4475848d8b8f10b4dbe1a66980c385f46ac00">>
2015-12-14 16:21:29.389 [debug] <0.1242.0>@ejabberd_http_bind:handle_sync_event:442 New request: {http_put,1598396,[{<<"xmlns">>,<<"http://jabber.org/protocol/httpbind">>},{<<"content">>,<<"text/xml; charset=utf-8">>},{<<"rid">>,<<"1598396">>},{<<"xml:lang">>,<<"en">>},{<<"sid">>,<<"92c4475848d8b8f10b4dbe1a66980c385f46ac00">>}],[],160,1,<<>>,{{127,0,0,1},50030}}
2015-12-14 16:21:29.389 [debug] <0.1242.0>@ejabberd_http_bind:handle_http_put_event:558 New request: {http_put,1598396,[{<<"xmlns">>,<<"http://jabber.org/protocol/httpbind">>},{<<"content">>,<<"text/xml; charset=utf-8">>},{<<"rid">>,<<"1598396">>},{<<"xml:lang">>,<<"en">>},{<<"sid">>,<<"92c4475848d8b8f10b4dbe1a66980c385f46ac00">>}],[],160,1,<<>>,{{127,0,0,1},50030}}
2015-12-14 16:21:29.389 [debug] <0.1242.0>@ejabberd_http_bind:rid_allow:852 Previous rid / New rid: 1598395/1598396
2015-12-14 16:21:29.389 [debug] <0.1242.0>@ejabberd_http_bind:process_http_put:591 Actually processing request: {http_put,1598396,[{<<"xmlns">>,<<"http://jabber.org/protocol/httpbind">>},{<<"content">>,<<"text/xml; charset=utf-8">>},{<<"rid">>,<<"1598396">>},{<<"xml:lang">>,<<"en">>},{<<"sid">>,<<"92c4475848d8b8f10b4dbe1a66980c385f46ac00">>}],[],160,1,<<>>,{{127,0,0,1},50030}}
2015-12-14 16:21:29.389 [debug] <0.1242.0>@ejabberd_http_bind:process_http_put:642  -- SaveKey: 
2015-12-14 16:21:29.389 [debug] <0.1242.0>@ejabberd_http_bind:process_http_put:654 reqlist: [{hbr,1598396,<<>>,[]},{hbr,1598395,<<>>,[]}]
2015-12-14 16:21:29.389 [debug] <0.1242.0>@ejabberd_http_bind:process_http_put:700 really sending now: []
2015-12-14 16:23:09.492 [info] <0.1242.0>@ejabberd_http_bind:handle_info:507 Session timeout. Closing the HTTP bind session: <<"92c4475848d8b8f10b4dbe1a66980c385f46ac00">>
2015-12-14 16:23:09.492 [debug] <0.1242.0>@ejabberd_http_bind:terminate:538 terminate: Deleting session 92c4475848d8b8f10b4dbe1a66980c385f46ac00

Hamlett Hamlett · Accepted Answer · 2015-12-14T19:39:23

I was making a mistake in the BoshClient script. There, in the "startSessionAndAuth" method, you can set the "wait" value, that I don't know in what stages you may want to wait but... it was set to 70 seconds by default. I set it to 0 and now is responding instantly with a new session id.

In the protocol definition its said:

Note: Clients that only support Polling Sessions MAY prevent the connection manager from waiting by setting 'wait' or 'hold' to "0". However, polling is NOT RECOMMENDED since the associated increase in bandwidth consumption and the decrease in responsiveness are both typically one or two orders of magnitude!

and it's exactly my case.

ejabberd BOSH takes too many minutes in HTTP pre-bind

1 Answers