http-bind problem

Just upgraded my server to 2.1.4 from 2.0.5 and previously was able to use jwchat against ejabberd, now I am unable to connect. Seems ejabberd is handling http-bind requests differently?

this is what the ejabberd debug log shows:

   
=INFO REPORT==== 2010-07-27 16:05:23 ===
I(<0.408.0>:ejabberd_listener:232) : (#Port<0.3728>) Accepted connection {{127,0,0,1},42407} -> {{127,0,0,1},5280}

=INFO REPORT==== 2010-07-27 16:05:23 ===
D(<0.410.0>:ejabberd_http:135) : S: [{["http-bind"],mod_http_bind}]

=INFO REPORT==== 2010-07-27 16:05:23 ===
I(<0.410.0>:ejabberd_http:137) : started: {tls,
                                           {tlssock,#Port<0.3728>,
                                            #Port<0.3733>}}

=INFO REPORT==== 2010-07-27 16:05:23 ===
D(<0.410.0>:ejabberd_http:864) : GOT ssl data "POST /http-bind/ HTTP/1.0\r\nHost: ejabberd.myserver.com:5280\r\nConnection: close\r\nOrigin: https://ejabberd.myserver.com\r\nUser-Agent: Mozilla/5.0 (Macintosh; U; Intel Mac OS X 10_6_4; en-us) AppleWebKit/533.16 (KHTML, like Gecko) Version/5.0 Safari/533.16\r\nContent-Type: text/xml; charset=UTF-8\r\nReferer: https://ejabberd.myserver.com/jwchat.html\r\nAccept: */*\r\nAccept-Language: en-us\r\nAccept-Encoding: gzip, deflate\r\nCookie: __utmc=79680135; __utma=79680135.1993210546.1208808684.1280164662.1280250457.698; __utmz=79680135.1280250457.698.88.utmcsr=feedburner|utmccn=Feed:%20myserverblog%20(The%20Server%20Blog)|utmcmd=feed|utmcct=Google%20Feedfetcher\r\nContent-Length: 301\r\n\r\n<body content='text/xml; charset=utf-8' hold='1' xmlns='http://jabber.org/protocol/httpbind' to='myserver.com' wait='280' rid='399983' route='xmpp:myserver.com:5222' secure='false' newkey='46077f4b8deacffc407ce59e60d558942f94986b' ver='1.6' xmlns:xmpp='urn:xmpp:xbosh' xmpp:version='1.0'/>"

=INFO REPORT==== 2010-07-27 16:05:23 ===
D(<0.410.0>:ejabberd_http:902) : Method: "POST"

=INFO REPORT==== 2010-07-27 16:05:23 ===
D(<0.410.0>:ejabberd_http:909) : URI: "/http-bind/"
Version: "HTTP/1.0"
L3: []

=INFO REPORT==== 2010-07-27 16:05:23 ===
D(<0.410.0>:ejabberd_http:868) : Parsed request {ok,
                                                 {http_request,'POST',
                                                  {abs_path,"/http-bind/"},
                                                  {1,0}}}

=INFO REPORT==== 2010-07-27 16:05:23 ===
D(<0.410.0>:ejabberd_http:254) : ({tlssock,#Port<0.3728>,#Port<0.3733>}) http query: 'POST' /http-bind/

=INFO REPORT==== 2010-07-27 16:05:23 ===
D(<0.410.0>:ejabberd_http:420) : client data: "<body content='text/xml; charset=utf-8' hold='1' xmlns='http://jabber.org/protocol/httpbind' to='myserver.com' wait='280' rid='399983' route='xmpp:myserver.com:5222' secure='false' newkey='46077f4b8deacffc407ce59e60d558942f94986b' ver='1.6' xmlns:xmpp='urn:xmpp:xbosh' xmpp:version='1.0'/>"

=INFO REPORT==== 2010-07-27 16:05:23 ===
D(<0.410.0>:ejabberd_http:323) : ["http-bind"] matches ["http-bind"]

=INFO REPORT==== 2010-07-27 16:05:23 ===
D(<0.410.0>:mod_http_bind:69) : Incoming data: <body content='text/xml; charset=utf-8' hold='1' xmlns='http://jabber.org/protocol/httpbind' to='myserver.com' wait='280' rid='399983' route='xmpp:myserver.com:5222' secure='false' newkey='46077f4b8deacffc407ce59e60d558942f94986b' ver='1.6' xmlns:xmpp='urn:xmpp:xbosh' xmpp:version='1.0'/>

=INFO REPORT==== 2010-07-27 16:05:23 ===
D(<0.410.0>:ejabberd_http_bind:1104) : --- incoming data ---
<body content='text/xml; charset=utf-8' hold='1' xmlns='http://jabber.org/protocol/httpbind' to='myserver.com' wait='280' rid='399983' route='xmpp:myserver.com:5222' secure='false' newkey='46077f4b8deacffc407ce59e60d558942f94986b' ver='1.6' xmlns:xmpp='urn:xmpp:xbosh' xmpp:version='1.0'/>
--- END ---

=INFO REPORT==== 2010-07-27 16:05:23 ===
D(<0.410.0>:ejabberd_http_bind:117) : Starting session

=INFO REPORT==== 2010-07-27 16:05:23 ===
D(<0.411.0>:ejabberd_http_bind:294) : started: {"3f955a14865cf73a74adc5a8e2d7c74350dd6d35",
                                                [],
                                                {{127,0,0,1},42407}}

=INFO REPORT==== 2010-07-27 16:05:23 ===
I(<0.412.0>:ejabberd_net:25) : gethostname {socket_state,ejabberd_http_bind,
                                            {http_bind,<0.411.0>,
                                             {{127,0,0,1},42407}},
                                            ejabberd_http_bind}

=INFO REPORT==== 2010-07-27 16:05:28 ===
D(<0.411.0>:ejabberd_http_bind:531) : terminate: Deleting session 3f955a14865cf73a74adc5a8e2d7c74350dd6d35

=INFO REPORT==== 2010-07-27 16:05:28 ===
D(<0.410.0>:ejabberd_http_bind:237) : got pid: <0.411.0>

=INFO REPORT==== 2010-07-27 16:05:28 ===
D(<0.410.0>:ejabberd_http_bind:267) : Create session: "3f955a14865cf73a74adc5a8e2d7c74350dd6d35"

=INFO REPORT==== 2010-07-27 16:05:28 ===
D(<0.410.0>:ejabberd_http_bind:788) : Looking for session: "3f955a14865cf73a74adc5a8e2d7c74350dd6d35"

as you can see it terminates the session before it is created. Additionally I get a 502 error in JWchat. Apache settings are all the same, as is my ejabberd configuration. Only thing that changed was that i upgraded to 2.1.4. Anyone have any ideas on how to fix? or should I wait for an update to jwchat?

tiredofnick wrote: Just

tiredofnick wrote:

Just upgraded my server to 2.1.4 from 2.0.5 and previously was able to use jwchat against ejabberd, now I am unable to connect.

Seems ejabberd is handling http-bind requests differently?

Surely, there were many changes in ejabberd's http-bind code between 2.0.5 and 2.1.4.

I have ejabberd 2.1.4, Erlang R13B04, serving HTTP using the internal mod_http_fileserver instead of Apache, and JWChat 1.0. It works for me.

I don't have those two reports:

=INFO REPORT==== 2010-07-27 16:05:23 ===
I(<0.412.0>:ejabberd_net:25) : gethostname {socket_state,ejabberd_http_bind,
                                            {http_bind,<0.411.0>,
                                             {{127,0,0,1},42407}},
                                            ejabberd_http_bind}

=INFO REPORT==== 2010-07-27 16:05:28 ===
D(<0.411.0>:ejabberd_http_bind:531) : terminate: Deleting session 3f955a14865cf73a74adc5a8e2d7c74350dd6d35

Just for curiosity, disable tls in the 5280 listener and try using HTTP instead of HTTPS.

Let's try to know more details about that termination. Apply this patch to ejabberd source code, compile and install the modified file. You can put loglevel to 4.

--- src/web/ejabberd_http_bind.erl
+++ src/web/ejabberd_http_bind.erl
@@ -527,8 +527,12 @@ handle_info(_, StateName, StateData) ->
 %% Purpose: Shutdown the fsm
 %% Returns: any
 %%----------------------------------------------------------------------
-terminate(_Reason, _StateName, StateData) ->
-    ?DEBUG("terminate: Deleting session ~s", [StateData#state.id]),
+terminate(Reason, StateName, StateData) ->
+    catch throw(error123),
+    Trace = erlang:get_stacktrace(),
+    ?INFO_MSG("terminate: Deleting session ~s for reason ~p, in"
+       " StateName ~p, with StateData: ~n~p~nand stacktrace: ~n~p",
+       [StateData#state.id, Reason, StateName, StateData, Trace]),
     mnesia:dirty_delete({http_bind, StateData#state.id}),
     send_receiver_reply(StateData#state.http_receiver, {ok, terminate}),
     case StateData#state.waiting_input of
Syndicate content