search

xmppo / node-xmpp-bosh

An XMPP BOSH & WebSocket server (connection manager) written on node.js using Javascript
https://github.com/xmppo/node-xmpp-bosh
263 stars 85 forks source link

No response returned to Strophe client #66

Closed Mingism closed 11 years ago

Mingism commented 11 years ago

I am not able to log in to my ejabberd server using strophe.js and with NXB in between. From the log I can see it does succesfully connect to the server, but after a while it terminates the connection. It looks like it turns idle after "a stream has been added". I would like to know how I can fix this. Strophe does connect to ejabberd's BOSH directly before I went and tried to put the NXB in between. Thank you in advance.

@parallels-Parallels-Virtual-Platform:/etc/ejabberd# node /var/backend/node_modules/node-xmpp-bosh/run-server.js 
+---------------------------------------------------------------------------------------------------------------------------------+
| Starting BOSH server 'v0.7.2' on 'http://192.168.1.149:5281/^\/http-bind(\/+)?$/' at 'Thu Apr 04 2013 09:40:39 GMT+0200 (CEST)' |
+---------------------------------------------------------------------------------------------------------------------------------+
[2013-04-04 07:40:39.370] [TRACE] [main.js:Object.exports.start_bosh:59] - Starting the Zilan BOSH server
+--------------------------------------------------------------------------------------------------------------+
| Starting WEBSOCKET server 'v0.7.2' on ws://192.168.1.149:5281' at 'Thu Apr 04 2013 09:40:39 GMT+0200 (CEST)' |
+--------------------------------------------------------------------------------------------------------------+
[2013-04-04 07:40:48.417] [TRACE] [http-server.js:Server.http_request_handler:315] - Processing GET request at location: /http-bind/
[2013-04-04 07:40:48.590] [TRACE] [http-server.js:Server.http_request_handler:315] - Processing GET request at location: /favicon.ico
[2013-04-04 07:40:54.309] [TRACE] [http-server.js:Server.http_request_handler:315] - Processing GET request at location: /http-bind/sysinfo
[2013-04-04 07:41:00.581] [TRACE] [http-server.js:Server.http_request_handler:315] - Processing OPTIONS request at location: /http-bind
[2013-04-04 07:41:00.586] [TRACE] [http-server.js:Server.http_request_handler:315] - Processing POST request at location: /http-bind
[2013-04-04 07:41:00.590] [DEBUG] [http-server.js:_unwrapped_on_end_callback:135] - RECD: <body rid="973686486" xmlns="http://jabber.org/protocol/httpbind" to="192.168.1.149" xml:lang="en" wait="60" hold="1" content="text/xml; charset=utf-8" ver="1.6" xmpp:version="1.0" xmlns:xmpp="urn:xmpp:xbosh"/>
[2013-04-04 07:41:00.594] [TRACE] [bosh.js:bosh_request_handler:235] - Processing Request
[2013-04-04 07:41:00.596] [TRACE] [bosh.js:process_bosh_request:150] - Session Creation
[2013-04-04 07:41:00.598] [TRACE] [session.js:Object.Session.reset_inactivity_timeout:524] - af99b311-1080-4601-a8b9-1aa294820022 reset_inactivity_timeout - 80 sec
[2013-04-04 07:41:00.599] [TRACE] [session.js:Object.Session.add_held_http_connection:480] - af99b311-1080-4601-a8b9-1aa294820022 add_held_http_connection - now holding 1 res obj
[2013-04-04 07:41:00.600] [TRACE] [xmpp-proxy-connector.js:Object.XMPPProxyConnector.stream_add:146] - af99b311-1080-4601-a8b9-1aa294820022 3cf7d128-c7cc-449a-9801-4c57efc06201 stream_add
[2013-04-04 07:41:00.604] [TRACE] [lookup-service.js:try_connect_SRV_lookup:105] - try_connect_SRV_lookup - 192.168.1.149, 5222
[2013-04-04 07:41:00.606] [TRACE] [session.js:Object.Session.enqueue_bosh_response:842] - af99b311-1080-4601-a8b9-1aa294820022 3cf7d128-c7cc-449a-9801-4c57efc06201
[2013-04-04 07:41:00.652] [TRACE] [lookup-service.js:Socket._on_socket_connect:84] - Connection to 192.168.1.149 succeeded
[2013-04-04 07:41:00.653] [TRACE] [xmpp-proxy.js:XMPPProxy.dutil.copy._on_connect:268] - af99b311-1080-4601-a8b9-1aa294820022 3cf7d128-c7cc-449a-9801-4c57efc06201 connected
[2013-04-04 07:41:00.659] [TRACE] [xmpp-proxy.js:XMPPProxy.dutil.copy.send:254] - af99b311-1080-4601-a8b9-1aa294820022 3cf7d128-c7cc-449a-9801-4c57efc06201 Sent: <stream:stream xmlns:stream="http://etherx.jabber.org/streams" xmlns="jabber:client" to="192.168.1.149" version="1.0">
[2013-04-04 07:41:00.664] [TRACE] [xmpp-proxy-connector.js:Object.<anonymous>:79] - af99b311-1080-4601-a8b9-1aa294820022 3cf7d128-c7cc-449a-9801-4c57efc06201 _on_xmpp_proxy_connected - connected
[2013-04-04 07:41:00.674] [TRACE] [bosh.js:Object._on_stream_added:242] - af99b311-1080-4601-a8b9-1aa294820022 3cf7d128-c7cc-449a-9801-4c57efc06201 stream-added
[2013-04-04 07:42:00.600] [TRACE] [session.js:Object.Session._send_no_requeue:874] - af99b311-1080-4601-a8b9-1aa294820022 ro: true
[2013-04-04 07:42:00.601] [TRACE] [session.js:Object.Session._send_no_requeue:879] - af99b311-1080-4601-a8b9-1aa294820022 ro.rid: 973686486, this.rid: 973686486
[2013-04-04 07:42:00.603] [DEBUG] [response.js:Object.Response.send_response:78] - af99b311-1080-4601-a8b9-1aa294820022 SENT(973686486): <body xmlns="http://jabber.org/protocol/httpbind"/>
[2013-04-04 07:42:00.608] [TRACE] [http-server.js:Server.http_request_handler:315] - Processing POST request at location: /http-bind
[2013-04-04 07:42:00.611] [DEBUG] [http-server.js:_unwrapped_on_end_callback:135] - RECD: <body rid="973686487" xmlns="http://jabber.org/protocol/httpbind"/>
[2013-04-04 07:42:00.613] [TRACE] [bosh.js:bosh_request_handler:235] - Processing Request
[2013-04-04 07:42:00.614] [TRACE] [bosh.js:process_bosh_request:171] - No_Session_ID Invalid Session
[2013-04-04 07:42:00.615] [TRACE] [session.js:Object.SessionStore.send_invalid_session_terminate_response:1191] - Sending invalid sid
[2013-04-04 07:42:00.616] [DEBUG] [response.js:Object.Response.send_response:78] - invalid-sid SENT(null): <body xmlns="http://jabber.org/protocol/httpbind" condition="item-not-found" message="Invalid session ID" type="terminate"/>
[2013-04-04 07:42:20.599] [INFO] [session.js:_on_session_inactivity_timeout_callback:528] - af99b311-1080-4601-a8b9-1aa294820022 Terminating Session due to inactivity
[2013-04-04 07:42:20.601] [INFO] [xmpp-proxy-connector.js:Object.XMPPProxyConnector.stream_terminate:192] - af99b311-1080-4601-a8b9-1aa294820022 3cf7d128-c7cc-449a-9801-4c57efc06201 stream_terminate
[2013-04-04 07:42:20.601] [INFO] [xmpp-proxy.js:XMPPProxy.dutil.copy.terminate:226] - af99b311-1080-4601-a8b9-1aa294820022 3cf7d128-c7cc-449a-9801-4c57efc06201 - terminating
[2013-04-04 07:42:20.603] [TRACE] [xmpp-proxy.js:XMPPProxy.dutil.copy.send:254] - af99b311-1080-4601-a8b9-1aa294820022 3cf7d128-c7cc-449a-9801-4c57efc06201 Sent: </stream:stream>
[2013-04-04 07:42:20.603] [TRACE] [session.js:Object.Session.get_response_object:704] - af99b311-1080-4601-a8b9-1aa294820022 get_response_object - holding 0 ro
[2013-04-04 07:42:20.604] [INFO] [session.js:Object.Session.send_terminate_response:585] - af99b311-1080-4601-a8b9-1aa294820022 send_terminate_response - ro: false, condition: no-condition
[2013-04-04 07:42:20.605] [TRACE] [session.js:Object.Session._send_no_requeue:874] - af99b311-1080-4601-a8b9-1aa294820022 ro: false
[2013-04-04 07:42:20.606] [TRACE] [session.js:Object.Session.get_response_object:704] - af99b311-1080-4601-a8b9-1aa294820022 get_response_object - holding 0 ro
dhruvbird commented 11 years ago

The Strophe client seems to be sending invalid requests:

[2013-04-04 07:42:00.611] [DEBUG] [http-server.js:_unwrapped_on_end_callback:135] - RECD: <body rid="973686487" xmlns="http://jabber.org/protocol/httpbind"/>
[2013-04-04 07:42:00.613] [TRACE] [bosh.js:bosh_request_handler:235] - Processing Request
[2013-04-04 07:42:00.614] [TRACE] [bosh.js:process_bosh_request:171] - No_Session_ID Invalid Session

Please could you confirm with another client such as JsJAC?

Mingism commented 11 years ago

I will check and let you know. But as you can see from the log, after 2013-04-04 07:41:00.674 it just idles for 60 seconds.

Mingism commented 11 years ago

Unfortunately it does not work with JsJAC either (it did connect straight with my ejabberd server). I believe it does connect though to the ejabberd server at:

[2013-04-05 10:46:12.145] [TRACE] [xmpp-proxy-connector.js:Object.<anonymous>:79] - a0ef24e4-995b-4c53-a268-e4c3e3a1f11e 5ee92024-6298-40f6-888d-07c33c422036 _on_xmpp_proxy_connected - connected

COMPLETE logfile:

+---------------------------------------------------------------------------------------------------------------------------------+
| Starting BOSH server 'v0.7.2' on 'http://192.168.1.149:5281/^\/http-bind(\/+)?$/' at 'Fri Apr 05 2013 12:45:08 GMT+0200 (CEST)' |
+---------------------------------------------------------------------------------------------------------------------------------+
[2013-04-05 10:45:08.975] [TRACE] [main.js:Object.exports.start_bosh:59] - Starting the Zilan BOSH server
+--------------------------------------------------------------------------------------------------------------+
| Starting WEBSOCKET server 'v0.7.2' on ws://192.168.1.149:5281' at 'Fri Apr 05 2013 12:45:08 GMT+0200 (CEST)' |
+--------------------------------------------------------------------------------------------------------------+
[2013-04-05 10:45:20.037] [TRACE] [http-server.js:Server.http_request_handler:315] - Processing POST request at location: /http-bind/
[2013-04-05 10:45:20.056] [DEBUG] [http-server.js:_unwrapped_on_end_callback:135] - RECD: <body content="text/xml; charset=utf-8" hold="1" xmlns="http://jabber.org/protocol/httpbind" to="192.168.1.149" wait="300" rid="549710" secure="false" newkey="ac08981f9a2ab89b19625c2a3536f6a251277496" xml:lang="en" ver="1.6" xmlns:xmpp="urn:xmpp:xbosh" xmp... [17 more characters]
[2013-04-05 10:45:20.057] [TRACE] [bosh.js:bosh_request_handler:235] - Processing Request
[2013-04-05 10:45:20.059] [TRACE] [bosh.js:process_bosh_request:150] - Session Creation
[2013-04-05 10:45:20.061] [TRACE] [session.js:Object.Session.reset_inactivity_timeout:524] - a0ef24e4-995b-4c53-a268-e4c3e3a1f11e reset_inactivity_timeout - 80 sec
[2013-04-05 10:45:20.063] [TRACE] [session.js:Object.Session.add_held_http_connection:480] - a0ef24e4-995b-4c53-a268-e4c3e3a1f11e add_held_http_connection - now holding 1 res obj
[2013-04-05 10:45:20.070] [TRACE] [xmpp-proxy-connector.js:Object.XMPPProxyConnector.stream_add:146] - a0ef24e4-995b-4c53-a268-e4c3e3a1f11e 5ee92024-6298-40f6-888d-07c33c422036 stream_add
[2013-04-05 10:45:20.078] [TRACE] [lookup-service.js:try_connect_SRV_lookup:105] - try_connect_SRV_lookup - 192.168.1.149, 5222
[2013-04-05 10:45:20.082] [TRACE] [session.js:Object.Session.enqueue_bosh_response:842] - a0ef24e4-995b-4c53-a268-e4c3e3a1f11e 5ee92024-6298-40f6-888d-07c33c422036
[2013-04-05 10:46:12.139] [TRACE] [lookup-service.js:Socket._on_socket_connect:84] - Connection to 192.168.1.149 succeeded
[2013-04-05 10:46:12.140] [TRACE] [xmpp-proxy.js:XMPPProxy.dutil.copy._on_connect:268] - a0ef24e4-995b-4c53-a268-e4c3e3a1f11e 5ee92024-6298-40f6-888d-07c33c422036 connected
[2013-04-05 10:46:12.144] [TRACE] [xmpp-proxy.js:XMPPProxy.dutil.copy.send:254] - a0ef24e4-995b-4c53-a268-e4c3e3a1f11e 5ee92024-6298-40f6-888d-07c33c422036 Sent: <stream:stream xmlns:stream="http://etherx.jabber.org/streams" xmlns="jabber:client" to="192.168.1.149" version="1.0">
[2013-04-05 10:46:12.145] [TRACE] [xmpp-proxy-connector.js:Object.<anonymous>:79] - a0ef24e4-995b-4c53-a268-e4c3e3a1f11e 5ee92024-6298-40f6-888d-07c33c422036 _on_xmpp_proxy_connected - connected
[2013-04-05 10:46:12.148] [TRACE] [bosh.js:Object._on_stream_added:242] - a0ef24e4-995b-4c53-a268-e4c3e3a1f11e 5ee92024-6298-40f6-888d-07c33c422036 stream-added
[2013-04-05 10:46:16.064] [TRACE] [session.js:Object.Session._send_no_requeue:874] - a0ef24e4-995b-4c53-a268-e4c3e3a1f11e ro: true
[2013-04-05 10:46:16.065] [TRACE] [session.js:Object.Session._send_no_requeue:879] - a0ef24e4-995b-4c53-a268-e4c3e3a1f11e ro.rid: 549710, this.rid: 549710
[2013-04-05 10:46:16.069] [DEBUG] [response.js:Object.Response.send_response:78] - a0ef24e4-995b-4c53-a268-e4c3e3a1f11e SENT(549710): <body xmlns="http://jabber.org/protocol/httpbind"/>
[2013-04-05 10:46:16.076] [TRACE] [http-server.js:Server.http_request_handler:315] - Processing POST request at location: /http-bind/
[2013-04-05 10:46:16.078] [DEBUG] [http-server.js:_unwrapped_on_end_callback:135] - RECD: <body rid="549711" sid="null" xmlns="http://jabber.org/protocol/httpbind" key="7ee258d0b079622126a1ad851d58d65efacb5cea"> </body>
[2013-04-05 10:46:16.081] [TRACE] [bosh.js:bosh_request_handler:235] - Processing Request
[2013-04-05 10:46:16.082] [TRACE] [bosh.js:process_bosh_request:171] - null Invalid Session
[2013-04-05 10:46:16.082] [TRACE] [session.js:Object.SessionStore.send_invalid_session_terminate_response:1191] - Sending invalid sid
[2013-04-05 10:46:16.084] [DEBUG] [response.js:Object.Response.send_response:78] - invalid-sid SENT(null): <body xmlns="http://jabber.org/protocol/httpbind" condition="item-not-found" message="Invalid session ID" type="terminate"/>
[2013-04-05 10:46:16.093] [TRACE] [http-server.js:Server.http_request_handler:315] - Processing POST request at location: /http-bind/
[2013-04-05 10:46:16.102] [DEBUG] [http-server.js:_unwrapped_on_end_callback:135] - RECD: <body rid="549712" sid="null" xmlns="http://jabber.org/protocol/httpbind" key="ae5c79c6efce69faaaa7f5e832361e4681ef429c" type="terminate"> </body>
[2013-04-05 10:46:16.103] [TRACE] [bosh.js:bosh_request_handler:235] - Processing Request
[2013-04-05 10:46:16.104] [TRACE] [bosh.js:process_bosh_request:171] - null Invalid Session
[2013-04-05 10:46:16.109] [TRACE] [session.js:Object.SessionStore.send_invalid_session_terminate_response:1191] - Sending invalid sid
[2013-04-05 10:46:16.110] [DEBUG] [response.js:Object.Response.send_response:78] - invalid-sid SENT(null): <body xmlns="http://jabber.org/protocol/httpbind" condition="item-not-found" message="Invalid session ID" type="terminate"/>
[2013-04-05 10:46:40.062] [INFO] [session.js:_on_session_inactivity_timeout_callback:528] - a0ef24e4-995b-4c53-a268-e4c3e3a1f11e Terminating Session due to inactivity
[2013-04-05 10:46:40.064] [INFO] [xmpp-proxy-connector.js:Object.XMPPProxyConnector.stream_terminate:192] - a0ef24e4-995b-4c53-a268-e4c3e3a1f11e 5ee92024-6298-40f6-888d-07c33c422036 stream_terminate
[2013-04-05 10:46:40.065] [INFO] [xmpp-proxy.js:XMPPProxy.dutil.copy.terminate:226] - a0ef24e4-995b-4c53-a268-e4c3e3a1f11e 5ee92024-6298-40f6-888d-07c33c422036 - terminating
[2013-04-05 10:46:40.067] [TRACE] [xmpp-proxy.js:XMPPProxy.dutil.copy.send:254] - a0ef24e4-995b-4c53-a268-e4c3e3a1f11e 5ee92024-6298-40f6-888d-07c33c422036 Sent: </stream:stream>
[2013-04-05 10:46:40.069] [TRACE] [session.js:Object.Session.get_response_object:704] - a0ef24e4-995b-4c53-a268-e4c3e3a1f11e get_response_object - holding 0 ro
[2013-04-05 10:46:40.070] [INFO] [session.js:Object.Session.send_terminate_response:585] - a0ef24e4-995b-4c53-a268-e4c3e3a1f11e send_terminate_response - ro: false, condition: no-condition
[2013-04-05 10:46:40.071] [TRACE] [session.js:Object.Session._send_no_requeue:874] - a0ef24e4-995b-4c53-a268-e4c3e3a1f11e ro: false
[2013-04-05 10:46:40.073] [TRACE] [session.js:Object.Session.get_response_object:704] - a0ef24e4-995b-4c53-a268-e4c3e3a1f11e get_response_object - holding 0 ro
dhruvbird commented 11 years ago

Yes, you're right. There's something fishy.

@anup @satyamshekhar Please could you verify if the following observation(s) are okay? (I'll try commiting a fix later in the day or over the weekend).

In the trace above, this line suggests that the 'sid' was not sent on the first response. Ideally, we would like the client to throw an error, but this doesn't happen since everything is usually a best-efforts things.

[2013-04-05 10:46:16.069] [DEBUG] [response.js:Object.Response.send_response:78] - a0ef24e4-995b-4c53-a268-e4c3e3a1f11e SENT(549710): <body xmlns="http://jabber.org/protocol/httpbind"/>
  1. https://github.com/dhruvbird/node-xmpp-bosh/blob/master/src/session.js#L630 -- 'msg' is never used.
  2. https://github.com/dhruvbird/node-xmpp-bosh/blob/master/src/session.js#L721 -- 'sid' is never added 'sid' to the list of attributes, which is causing the SID to not be sent in certain cases.
satyamshekhar commented 11 years ago

So I think the issue is slightly different.

@kmtsar : Can you post the config that you are running nxb with? and also the full session creation request parameter from the log file?

@dhruvbird : I believe, the problem is happening in pidgin compatible mode, when we dont send the session creation response immediately. But then the wait period expires before we are able to send the session creation response so we send the empty body.

PS: Like you pointed out, there is lot of dead code lying around. We should create an issue to clean that up.

dhruvbird commented 11 years ago

@satyamshekhar +1 about the config file - going forward, we should print out the config. variables in debug mode. Will file tasks for both.

Mingism commented 11 years ago

Config file:

// -*-  tab-width:4  -*-

exports.config = {
    port: 5281, 
    host: '192.168.1.149', 
    path: /^\/http-bind(\/+)?$/, 
    logging: 'DEBUG', 

    // The maximum number of bytes that the BOSH server will 
    // "hold" from the client
    max_data_held: 100000, 

    // Terminate the session if a stanza from XMPP server for 
    // a stream exceeds max_xmpp_stanza_size bytes
    max_xmpp_stanza_size: 500000, 

    // Don't entertain more than 'max_bosh_connections' simultaneous 
    // connections on any BOSH session. This is related to the 'hold'
    // attribute
    max_bosh_connections: 2, 

    // The maximum number of packets on either side of the current 'rid'
    // that we are willing to accept.
    window_size: 2, 

    // How much time (in second) should we hold a response object 
    // before sending and empty response on it?
    default_inactivity: 70, 

    max_inactivity: 160, 

    // The value (in second) of keepalive to set on the HTTP response 
    // socket
    http_socket_keepalive: 60, 

    // The maximum number of active streams allowed per BOSH session
    max_streams_per_session: 8, 

    http_headers: { }, 

    // 
    // A list of Domains for which TLS should NOT be used 
    // if the XMPP server supports STARTTLS but does NOT
    // require it.
    // 
    // See this link for details:
    // http://code.google.com/p/node-xmpp-bosh/issues/detail?id=11
    // 
    no_tls_domains: [ /* 'chat.facebook.com' */ ], 

    // Set to 'true' if you want:
    // 
    // 1. The session creation response to contain the <stream:features/> tag.
    // 2. NO multiple streams support (only supports a single stream
    // per session in this mode).
    // 
    // Useful to work around a pidgin (libpurple) bug.
    // 
    pidgin_compatible: true,

    // The maximum length of an XML stanza to be printed. Set to -1
    // for unlimited line length.
    trim_default_length: 256,

    // The password used to protect the /PATH/sysinfo/ URL. The
    // username to use when prompted for authentication is 'admin'.
    system_info_password: 'xxxx'
};

Log with level on "DEBUG":

+---------------------------------------------------------------------------------------------------------------------------------+
| Starting BOSH server 'v0.7.2' on 'http://192.168.1.149:5281/^\/http-bind(\/+)?$/' at 'Sat Apr 06 2013 17:07:58 GMT+0200 (CEST)' |
+---------------------------------------------------------------------------------------------------------------------------------+
+--------------------------------------------------------------------------------------------------------------+
| Starting WEBSOCKET server 'v0.7.2' on ws://192.168.1.149:5281' at 'Sat Apr 06 2013 17:07:58 GMT+0200 (CEST)' |
+--------------------------------------------------------------------------------------------------------------+
[2013-04-06 15:08:11.640] [DEBUG] [http-server.js:_unwrapped_on_end_callback:135] - RECD: <body rid="3916078972" xmlns="http://jabber.org/protocol/httpbind" to="parallels-parallels-virtual-platform" xml:lang="en" wait="60" hold="1" content="text/xml; charset=utf-8" ver="1.6" xmpp:version="1.0" xmlns:xmpp="urn:xmpp:xbosh"/>
[2013-04-06 15:08:11.686] [DEBUG] [response.js:Object.Response.send_response:78] - 4ee010c3-9dc7-43d1-95e3-ccd07474e815 SENT(3916078972): <body xmlns="http://jabber.org/protocol/httpbind" stream="93a56826-395b-4bfe-bb4c-d9d798930d4f" sid="4ee010c3-9dc7-43d1-95e3-ccd07474e815" wait="60" ver="1.6" polling="35" inactivity="70" requests="2" hold="1" from="parallels-parallels-virtual-platform" co... [97 more characters]
[2013-04-06 15:08:11.697] [DEBUG] [http-server.js:_unwrapped_on_end_callback:135] - RECD: <body rid="3916078973" xmlns="http://jabber.org/protocol/httpbind" sid="4ee010c3-9dc7-43d1-95e3-ccd07474e815"/>
[2013-04-06 15:09:11.705] [DEBUG] [response.js:Object.Response.send_response:78] - 4ee010c3-9dc7-43d1-95e3-ccd07474e815 SENT(3916078973): <body xmlns="http://jabber.org/protocol/httpbind"/>
[2013-04-06 15:09:11.717] [DEBUG] [http-server.js:_unwrapped_on_end_callback:135] - RECD: <body rid="3916078974" xmlns="http://jabber.org/protocol/httpbind" sid="4ee010c3-9dc7-43d1-95e3-ccd07474e815"/>
[2013-04-06 15:10:11.723] [DEBUG] [response.js:Object.Response.send_response:78] - 4ee010c3-9dc7-43d1-95e3-ccd07474e815 SENT(3916078974): <body xmlns="http://jabber.org/protocol/httpbind"/>
[2013-04-06 15:10:11.760] [DEBUG] [http-server.js:_unwrapped_on_end_callback:135] - RECD: <body rid="3916078975" xmlns="http://jabber.org/protocol/httpbind" sid="4ee010c3-9dc7-43d1-95e3-ccd07474e815"/>
[2013-04-06 15:11:11.775] [DEBUG] [response.js:Object.Response.send_response:78] - 4ee010c3-9dc7-43d1-95e3-ccd07474e815 SENT(3916078975): <body xmlns="http://jabber.org/protocol/httpbind"/>
[2013-04-06 15:11:11.782] [DEBUG] [http-server.js:_unwrapped_on_end_callback:135] - RECD: <body rid="3916078976" xmlns="http://jabber.org/protocol/httpbind" sid="4ee010c3-9dc7-43d1-95e3-ccd07474e815"/>
[2013-04-06 15:12:11.801] [DEBUG] [response.js:Object.Response.send_response:78] - 4ee010c3-9dc7-43d1-95e3-ccd07474e815 SENT(3916078976): <body xmlns="http://jabber.org/protocol/httpbind"/>
[2013-04-06 15:12:11.809] [DEBUG] [http-server.js:_unwrapped_on_end_callback:135] - RECD: <body rid="3916078977" xmlns="http://jabber.org/protocol/httpbind" sid="4ee010c3-9dc7-43d1-95e3-ccd07474e815"/>
[2013-04-06 15:13:11.815] [DEBUG] [response.js:Object.Response.send_response:78] - 4ee010c3-9dc7-43d1-95e3-ccd07474e815 SENT(3916078977): <body xmlns="http://jabber.org/protocol/httpbind"/>
[2013-04-06 15:13:11.827] [DEBUG] [http-server.js:_unwrapped_on_end_callback:135] - RECD: <body rid="3916078978" xmlns="http://jabber.org/protocol/httpbind" sid="4ee010c3-9dc7-43d1-95e3-ccd07474e815"/>
satyamshekhar commented 11 years ago

@kmtsar I believe NXB would run fine if you set pidgin_compatible: false in the config. That feature seems buggy right now. We will put in a fix soon.

@dhruvbird I don't remember very clearly what was required to support pidgin. The bug is that the wait period of a request expires before we are able to send the session creation response due to https://github.com/dhruvbird/node-xmpp-bosh/blob/master/src/session.js#L461 .

dhruvbird commented 11 years ago

@satyamshekhar The older log entries here: http://pastebin.com/8EkghW6W seem to suggest that pidgin_compatible is true, but the latest entries below seem to suggest otherwise.

[2013-04-06 15:08:11.640] [DEBUG] [http-server.js:_unwrapped_on_end_callback:135] - RECD: <body rid="3916078972" xmlns="http://jabber.org/protocol/httpbind" to="parallels-parallels-virtual-platform" xml:lang="en" wait="60" hold="1" content="text/xml; charset=utf-8" ver="1.6" xmpp:version="1.0" xmlns:xmpp="urn:xmpp:xbosh"/>
[2013-04-06 15:08:11.686] [DEBUG] [response.js:Object.Response.send_response:78] - 4ee010c3-9dc7-43d1-95e3-ccd07474e815 SENT(3916078972): <body xmlns="http://jabber.org/protocol/httpbind" stream="93a56826-395b-4bfe-bb4c-d9d798930d4f" sid="4ee010c3-9dc7-43d1-95e3-ccd07474e815" wait="60" ver="1.6" polling="35" inactivity="70" requests="2" hold="1" from="parallels-parallels-virtual-platform" co... [97 more characters]
[2013-04-06 15:08:11.697] [DEBUG] [http-server.js:_unwrapped_on_end_callback:135] - RECD: <body rid="3916078973" xmlns="http://jabber.org/protocol/httpbind" sid="4ee010c3-9dc7-43d1-95e3-ccd07474e815"/>
[2013-04-06 15:09:11.705] [DEBUG] [response.js:Object.Response.send_response:78] - 4ee010c3-9dc7-43d1-95e3-ccd07474e815 SENT(3916078973): <body xmlns="http://jabber.org/protocol/httpbind"/>
[2013-04-06 15:09:11.717] [DEBUG] [http-server.js:_unwrapped_on_end_callback:135] - RECD: <body rid="3916078974" xmlns="http://jabber.org/protocol/httpbind" sid="4ee010c3-9dc7-43d1-95e3-ccd07474e815"/>
...

@satyamshekhar So, pidgin assumes that the 1st response will be a <stream:features/> but since NXB eagerly sends a session creation response (even before the upstream XMPP server has been contacted), pidgin compatible mode was meant to stop that from happening by delaying the response till the upstream XMPP server has responded. It is also likely that in @kmtsar 's configuration, the upstream XMPP server can not be contacted. http://pastebin.com/8EkghW6W seems to suggest that the connection succeeded, but there was no response from the XMPP proxy.

@kmtsar Are you sure the XMPP server is up and running and accepting connections? Can you log in to it normally using pidgin?

satyamshekhar commented 11 years ago

@dhruvbird I don't think there is anything wrong with the latest log entries.

I agree the XMPP server didn't respond as expected. <body rid="973686486" xmlns="http://jabber.org/protocol/httpbind" to="192.168.1.149" ... seemed interesting because of the IP address. However, the behavior of NXB is not correct anyways. The first response should always carry sid. I don't the we are handling the case where wait period times out before connection to the backend XMPP server succeeds.

@kmtsar you should check the XMPP server's log to see what is the behaviour there.

dhruvbird commented 11 years ago

@satyamshekhar You're right about not handling those cases. Would like to know your comments on 8ada5ca930b520023503f4a3f49b4094691f5549

Mingism commented 11 years ago

@dhruvbird Yes, the XMPP server is running correctly, because previously I was running it without NXB between my Strophe webclient (BOSH over 5280) and an iPhone simulator (through port 5222).

@satyamshekhar I am running the server locally and using an IP address instead of a host/server name. Running it with Pidgin=false did not work as well.

satyamshekhar commented 11 years ago

@dhruvbird Added comment for the commit.

@kmtsar Can you please copy paste the log to tell us how it is failing after you have set pidgin_compatibility=false?

dhruvbird commented 11 years ago

@satyamshekhar Where did you comment? I don't see anything.

@kmtsar Can you try running this version and let us know what you see:

git clone git@github.com:dhruvbird/node-xmpp-bosh.git -b fix-issue-66

Could you bypass the config file altogether and let it run with the default options if possible? FYI, --pidgin=false isn't a command line option. IIRC, very few things can be set from the command line options, which is a little sad :-(

dhruvbird commented 11 years ago

@kmtsar What is the JID you are using to connect to the XMPP server?

satyamshekhar commented 11 years ago

That comment was for the previous commit. Added new comment for new commit. :)

Mingism commented 11 years ago

@dhruvbird: I was using the local ip address as a JID, e.g. 316xxxxxxxx@192.168.1.149, but I am going to use hostname instead from now on. Would this be a problem for NXB?

@dhruvbird @satyamshekhar: I will run it tomorrow with the fix, both with pidgin = false and pidgin = true and using the hostname in the JID.

dhruvbird commented 11 years ago

@kmtsar I think I am able to reproduce your issue locally, and it's not fixed. Will update when it is.

Mingism commented 11 years ago

@dhruvbird Allright, let me know when I can test.

dhruvbird commented 11 years ago

There's actually a bug in the dns-srv library which peeked into the internals of an EventEmitter, but the structure has changed with the new version of node.js, so it's been failing with node > some version. Will post a fix soon.

Mingism commented 11 years ago

Is that something that node.js should have kept backwards compatible?

dhruvbird commented 11 years ago

@satyamshekhar I think this commit should fix the fact that the 'data' event wasn't being raised on the socket correctly. https://github.com/dhruvbird/dns-srv/commit/e8e4d6fe2524d02726b10591d201655cae3bc3d8

dhruvbird commented 11 years ago

@kmtsar Not really. I was definitely looking at the implementation to see how to get the functionality I want, so I wasn't strictly following the public API. Even now, I don't have a way to do what I want to so, am again relying on implementation details.

dhruvbird commented 11 years ago

@kmtsar Okay, the fix has landed on that branch. Do let me know if it works for you. You'll have up run npm install . from the code directory since one of the dependencies has changed (the version).

Mingism commented 11 years ago

@dhruvbird Unfortunately it it still not responding to the strophe client.

Pidgin set to false:

+---------------------------------------------------------------------------------------------------------------------------------+
| Starting BOSH server 'v0.7.3' on 'http://192.168.1.149:5281/^\/http-bind(\/+)?$/' at 'Thu Apr 11 2013 10:01:59 GMT+0200 (CEST)' |
+---------------------------------------------------------------------------------------------------------------------------------+
[2013-04-11 08:01:59.232] [DEBUG] [options.js:new:34] - Node.js version: v0.10.2
[2013-04-11 08:01:59.233] [DEBUG] [options.js:UNKNOWN:00] - HTTP_GET_RESPONSE_HEADERS::Content-Type => text/html; charset=UTF-8
[2013-04-11 08:01:59.234] [DEBUG] [options.js:UNKNOWN:00] - HTTP_GET_RESPONSE_HEADERS::Cache-Control => no-cache, no-store
[2013-04-11 08:01:59.234] [DEBUG] [options.js:UNKNOWN:00] - HTTP_GET_RESPONSE_HEADERS::Access-Control-Allow-Origin => *
[2013-04-11 08:01:59.235] [DEBUG] [options.js:UNKNOWN:00] - HTTP_GET_RESPONSE_HEADERS::Access-Control-Allow-Headers => Content-Type, x-requested-with, Set-Cookie
[2013-04-11 08:01:59.236] [DEBUG] [options.js:UNKNOWN:00] - HTTP_GET_RESPONSE_HEADERS::Access-Control-Allow-Methods => OPTIONS, GET, POST
[2013-04-11 08:01:59.236] [DEBUG] [options.js:UNKNOWN:00] - HTTP_GET_RESPONSE_HEADERS::Access-Control-Max-Age => 14400
[2013-04-11 08:01:59.237] [DEBUG] [options.js:UNKNOWN:00] - HTTP_POST_RESPONSE_HEADERS::Content-Type => text/xml; charset=UTF-8
[2013-04-11 08:01:59.237] [DEBUG] [options.js:UNKNOWN:00] - HTTP_POST_RESPONSE_HEADERS::Access-Control-Allow-Origin => *
[2013-04-11 08:01:59.238] [DEBUG] [options.js:UNKNOWN:00] - HTTP_POST_RESPONSE_HEADERS::Access-Control-Allow-Headers => Content-Type, x-requested-with, Set-Cookie
[2013-04-11 08:01:59.238] [DEBUG] [options.js:UNKNOWN:00] - HTTP_POST_RESPONSE_HEADERS::Access-Control-Allow-Methods => OPTIONS, GET, POST
[2013-04-11 08:01:59.239] [DEBUG] [options.js:UNKNOWN:00] - HTTP_POST_RESPONSE_HEADERS::Access-Control-Max-Age => 14400
[2013-04-11 08:01:59.239] [DEBUG] [options.js:UNKNOWN:00] - HTTP_OPTIONS_RESPONSE_HEADERS::Access-Control-Allow-Origin => *
[2013-04-11 08:01:59.240] [DEBUG] [options.js:UNKNOWN:00] - HTTP_OPTIONS_RESPONSE_HEADERS::Access-Control-Allow-Headers => Content-Type, x-requested-with, Set-Cookie
[2013-04-11 08:01:59.241] [DEBUG] [options.js:UNKNOWN:00] - HTTP_OPTIONS_RESPONSE_HEADERS::Access-Control-Allow-Methods => POST, GET, OPTIONS
[2013-04-11 08:01:59.241] [DEBUG] [options.js:UNKNOWN:00] - HTTP_OPTIONS_RESPONSE_HEADERS::Access-Control-Max-Age => 14400
[2013-04-11 08:01:59.248] [DEBUG] [options.js:new:80] - path: /^\/http-bind(\/+)?$/
[2013-04-11 08:01:59.249] [DEBUG] [options.js:new:108] - MAX_DATA_HELD: 100000
[2013-04-11 08:01:59.250] [DEBUG] [options.js:new:109] - MAX_BOSH_CONNECTIONS: 2
[2013-04-11 08:01:59.253] [DEBUG] [options.js:new:110] - WINDOW_SIZE: 2
[2013-04-11 08:01:59.254] [DEBUG] [options.js:new:111] - DEFAULT_INACTIVITY: 70
[2013-04-11 08:01:59.255] [DEBUG] [options.js:new:112] - MAX_INACTIVITY: 160
[2013-04-11 08:01:59.256] [DEBUG] [options.js:new:113] - HTTP_SOCKET_KEEPALIVE: 60
[2013-04-11 08:01:59.256] [DEBUG] [options.js:new:114] - MAX_STREAMS_PER_SESSION: 8
[2013-04-11 08:01:59.257] [DEBUG] [options.js:new:115] - PIDGIN_COMPATIBLE: false
[2013-04-11 08:01:59.257] [DEBUG] [options.js:new:116] - SYSTEM_INFO_PASSWORD: [SET]
[2013-04-11 08:01:59.263] [TRACE] [main.js:Object.exports.start_bosh:59] - Starting the BOSH server
+--------------------------------------------------------------------------------------------------------------+
| Starting WEBSOCKET server 'v0.7.3' on ws://192.168.1.149:5281' at 'Thu Apr 11 2013 10:01:59 GMT+0200 (CEST)' |
+--------------------------------------------------------------------------------------------------------------+
[2013-04-11 08:02:10.047] [TRACE] [http-server.js:Server.http_request_handler:315] - Processing POST request at location: /http-bind
[2013-04-11 08:02:10.051] [DEBUG] [http-server.js:_unwrapped_on_end_callback:135] - RECD: <body rid="3563386930" xmlns="http://jabber.org/protocol/httpbind" to="parallels-parallels-virtual-platform" xml:lang="en" wait="60" hold="1" content="text/xml; charset=utf-8" ver="1.6" xmpp:version="1.0" xmlns:xmpp="urn:xmpp:xbosh"/>
[2013-04-11 08:02:10.052] [TRACE] [bosh.js:bosh_request_handler:235] - Processing Request
[2013-04-11 08:02:10.054] [TRACE] [bosh.js:process_bosh_request:150] - Session Creation
[2013-04-11 08:02:10.056] [TRACE] [session.js:Object.Session.reset_inactivity_timeout:543] - 39473f2b-f2c0-4b96-8bfe-6b4829007cce reset_inactivity_timeout - 80 sec
[2013-04-11 08:02:10.059] [TRACE] [session.js:Object.Session.add_held_http_connection:495] - 39473f2b-f2c0-4b96-8bfe-6b4829007cce add_held_http_connection - now holding 1 res obj
[2013-04-11 08:02:10.061] [TRACE] [xmpp-proxy-connector.js:Object.XMPPProxyConnector.stream_add:146] - 39473f2b-f2c0-4b96-8bfe-6b4829007cce 42686dd8-1816-45ee-9745-a97b08bf708c stream_add
[2013-04-11 08:02:10.065] [TRACE] [lookup-service.js:try_connect_SRV_lookup:112] - try_connect_SRV_lookup - parallels-parallels-virtual-platform, 5222
[2013-04-11 08:02:10.067] [TRACE] [session.js:Object.Session.enqueue_bosh_response:861] - 39473f2b-f2c0-4b96-8bfe-6b4829007cce 42686dd8-1816-45ee-9745-a97b08bf708c
[2013-04-11 08:02:10.069] [TRACE] [session.js:Object.Session.send_pending_responses:794] - 39473f2b-f2c0-4b96-8bfe-6b4829007cce pending.length: 0, Holding 1 response objects
[2013-04-11 08:02:10.070] [TRACE] [session.js:Object.Session._stitch_new_response:753] - 39473f2b-f2c0-4b96-8bfe-6b4829007cce _stitch_new_response - #streams: 1, next_stream: 0
[2013-04-11 08:02:10.071] [TRACE] [session.js:Object.Session._stitch_new_response:770] - 39473f2b-f2c0-4b96-8bfe-6b4829007cce 42686dd8-1816-45ee-9745-a97b08bf708c _stitch_response_for_stream - stitched
[2013-04-11 08:02:10.072] [TRACE] [session.js:Object.Session.get_response_object:719] - 39473f2b-f2c0-4b96-8bfe-6b4829007cce get_response_object - return ro with rid: 3563386930
[2013-04-11 08:02:10.073] [TRACE] [session.js:Object.Session.get_response_object:723] - 39473f2b-f2c0-4b96-8bfe-6b4829007cce get_response_object - holding 0 ro
[2013-04-11 08:02:10.079] [TRACE] [session.js:Object.Session.send_pending_responses:809] - 39473f2b-f2c0-4b96-8bfe-6b4829007cce send_pending_responses - ro: true, pending_stitched_responses: 1 - sending
[2013-04-11 08:02:10.088] [TRACE] [session.js:Object.Session._send_no_requeue:893] - 39473f2b-f2c0-4b96-8bfe-6b4829007cce ro: true
[2013-04-11 08:02:10.090] [TRACE] [session.js:Object.Session._send_no_requeue:898] - 39473f2b-f2c0-4b96-8bfe-6b4829007cce ro.rid: 3563386930, this.rid: 3563386930
[2013-04-11 08:02:10.094] [DEBUG] [response.js:Object.Response.send_response:85] - 39473f2b-f2c0-4b96-8bfe-6b4829007cce SENT(3563386930): <body xmlns="http://jabber.org/protocol/httpbind" stream="42686dd8-1816-45ee-9745-a97b08bf708c" sid="39473f2b-f2c0-4b96-8bfe-6b4829007cce" wait="60" ver="1.6" polling="35" inactivity="70" requests="2" hold="1" from="parallels-parallels-virtual-platform" co... [97 more characters]
[2013-04-11 08:02:10.102] [TRACE] [http-server.js:Server.http_request_handler:315] - Processing POST request at location: /http-bind
[2013-04-11 08:02:10.103] [DEBUG] [http-server.js:_unwrapped_on_end_callback:135] - RECD: <body rid="3563386931" xmlns="http://jabber.org/protocol/httpbind" sid="39473f2b-f2c0-4b96-8bfe-6b4829007cce"/>
[2013-04-11 08:02:10.104] [TRACE] [bosh.js:bosh_request_handler:235] - Processing Request
[2013-04-11 08:02:10.105] [TRACE] [bosh.js:process_bosh_request:176] - 39473f2b-f2c0-4b96-8bfe-6b4829007cce NO_Stream req.rid: 3563386931, session.rid: 3563386930
[2013-04-11 08:02:10.105] [TRACE] [session.js:Object.Session.is_valid_packet:248] - 39473f2b-f2c0-4b96-8bfe-6b4829007cce is_valid_packet - node.attrs.rid: 3563386931, state.rid: 3563386930
[2013-04-11 08:02:10.106] [TRACE] [session.js:Object.Session.reset_inactivity_timeout:543] - 39473f2b-f2c0-4b96-8bfe-6b4829007cce reset_inactivity_timeout - 80 sec
[2013-04-11 08:02:10.114] [TRACE] [session.js:Object.Session.add_request_for_processing:370] - 39473f2b-f2c0-4b96-8bfe-6b4829007cce add_request_for_processing - session.rid: 3563386930
[2013-04-11 08:02:10.119] [TRACE] [session.js:Object.Session.add_held_http_connection:495] - 39473f2b-f2c0-4b96-8bfe-6b4829007cce add_held_http_connection - now holding 1 res obj
[2013-04-11 08:02:10.122] [TRACE] [session.js:Object.Session.process_requests:330] - 39473f2b-f2c0-4b96-8bfe-6b4829007cce process_requests - session.rid: 3563386930
[2013-04-11 08:02:10.123] [TRACE] [session.js:Object.Session.process_requests:349] - 39473f2b-f2c0-4b96-8bfe-6b4829007cce updated session.rid to 3563386931
[2013-04-11 08:02:10.123] [TRACE] [session.js:Object.Session._process_one_request:265] - 39473f2b-f2c0-4b96-8bfe-6b4829007cce 42686dd8-1816-45ee-9745-a97b08bf708c _process_one_request - session.rid: 3563386931, valid_stream: true
[2013-04-11 08:02:10.125] [TRACE] [session.js:Object.Session.send_pending_responses:794] - 39473f2b-f2c0-4b96-8bfe-6b4829007cce pending.length: 0, Holding 1 response objects
[2013-04-11 08:02:10.125] [TRACE] [session.js:Object.Session._stitch_new_response:753] - 39473f2b-f2c0-4b96-8bfe-6b4829007cce _stitch_new_response - #streams: 1, next_stream: 0
[2013-04-11 08:02:10.126] [TRACE] [session.js:Object.Session.send_pending_responses:820] - 39473f2b-f2c0-4b96-8bfe-6b4829007cce send_pending_responses - nothing to send, 0 pending - return

Pidgin set to true:

+---------------------------------------------------------------------------------------------------------------------------------+
| Starting BOSH server 'v0.7.3' on 'http://192.168.1.149:5281/^\/http-bind(\/+)?$/' at 'Thu Apr 11 2013 10:10:44 GMT+0200 (CEST)' |
+---------------------------------------------------------------------------------------------------------------------------------+
[2013-04-11 08:10:44.663] [DEBUG] [options.js:new:34] - Node.js version: v0.10.2
[2013-04-11 08:10:44.664] [DEBUG] [options.js:UNKNOWN:00] - HTTP_GET_RESPONSE_HEADERS::Content-Type => text/html; charset=UTF-8
[2013-04-11 08:10:44.665] [DEBUG] [options.js:UNKNOWN:00] - HTTP_GET_RESPONSE_HEADERS::Cache-Control => no-cache, no-store
[2013-04-11 08:10:44.665] [DEBUG] [options.js:UNKNOWN:00] - HTTP_GET_RESPONSE_HEADERS::Access-Control-Allow-Origin => *
[2013-04-11 08:10:44.666] [DEBUG] [options.js:UNKNOWN:00] - HTTP_GET_RESPONSE_HEADERS::Access-Control-Allow-Headers => Content-Type, x-requested-with, Set-Cookie
[2013-04-11 08:10:44.666] [DEBUG] [options.js:UNKNOWN:00] - HTTP_GET_RESPONSE_HEADERS::Access-Control-Allow-Methods => OPTIONS, GET, POST
[2013-04-11 08:10:44.667] [DEBUG] [options.js:UNKNOWN:00] - HTTP_GET_RESPONSE_HEADERS::Access-Control-Max-Age => 14400
[2013-04-11 08:10:44.668] [DEBUG] [options.js:UNKNOWN:00] - HTTP_POST_RESPONSE_HEADERS::Content-Type => text/xml; charset=UTF-8
[2013-04-11 08:10:44.668] [DEBUG] [options.js:UNKNOWN:00] - HTTP_POST_RESPONSE_HEADERS::Access-Control-Allow-Origin => *
[2013-04-11 08:10:44.668] [DEBUG] [options.js:UNKNOWN:00] - HTTP_POST_RESPONSE_HEADERS::Access-Control-Allow-Headers => Content-Type, x-requested-with, Set-Cookie
[2013-04-11 08:10:44.669] [DEBUG] [options.js:UNKNOWN:00] - HTTP_POST_RESPONSE_HEADERS::Access-Control-Allow-Methods => OPTIONS, GET, POST
[2013-04-11 08:10:44.669] [DEBUG] [options.js:UNKNOWN:00] - HTTP_POST_RESPONSE_HEADERS::Access-Control-Max-Age => 14400
[2013-04-11 08:10:44.670] [DEBUG] [options.js:UNKNOWN:00] - HTTP_OPTIONS_RESPONSE_HEADERS::Access-Control-Allow-Origin => *
[2013-04-11 08:10:44.671] [DEBUG] [options.js:UNKNOWN:00] - HTTP_OPTIONS_RESPONSE_HEADERS::Access-Control-Allow-Headers => Content-Type, x-requested-with, Set-Cookie
[2013-04-11 08:10:44.672] [DEBUG] [options.js:UNKNOWN:00] - HTTP_OPTIONS_RESPONSE_HEADERS::Access-Control-Allow-Methods => POST, GET, OPTIONS
[2013-04-11 08:10:44.672] [DEBUG] [options.js:UNKNOWN:00] - HTTP_OPTIONS_RESPONSE_HEADERS::Access-Control-Max-Age => 14400
[2013-04-11 08:10:44.679] [DEBUG] [options.js:new:80] - path: /^\/http-bind(\/+)?$/
[2013-04-11 08:10:44.679] [DEBUG] [options.js:new:108] - MAX_DATA_HELD: 100000
[2013-04-11 08:10:44.683] [DEBUG] [options.js:new:109] - MAX_BOSH_CONNECTIONS: 2
[2013-04-11 08:10:44.684] [DEBUG] [options.js:new:110] - WINDOW_SIZE: 2
[2013-04-11 08:10:44.684] [DEBUG] [options.js:new:111] - DEFAULT_INACTIVITY: 70
[2013-04-11 08:10:44.686] [DEBUG] [options.js:new:112] - MAX_INACTIVITY: 160
[2013-04-11 08:10:44.686] [DEBUG] [options.js:new:113] - HTTP_SOCKET_KEEPALIVE: 60
[2013-04-11 08:10:44.687] [DEBUG] [options.js:new:114] - MAX_STREAMS_PER_SESSION: 8
[2013-04-11 08:10:44.687] [DEBUG] [options.js:new:115] - PIDGIN_COMPATIBLE: true
[2013-04-11 08:10:44.688] [DEBUG] [options.js:new:116] - SYSTEM_INFO_PASSWORD: [SET]
[2013-04-11 08:10:44.694] [TRACE] [main.js:Object.exports.start_bosh:59] - Starting the BOSH server
+--------------------------------------------------------------------------------------------------------------+
| Starting WEBSOCKET server 'v0.7.3' on ws://192.168.1.149:5281' at 'Thu Apr 11 2013 10:10:44 GMT+0200 (CEST)' |
+--------------------------------------------------------------------------------------------------------------+
[2013-04-11 08:11:05.487] [TRACE] [http-server.js:Server.http_request_handler:315] - Processing POST request at location: /http-bind
[2013-04-11 08:11:05.492] [DEBUG] [http-server.js:_unwrapped_on_end_callback:135] - RECD: <body rid="3580127578" xmlns="http://jabber.org/protocol/httpbind" to="parallels-parallels-virtual-platform" xml:lang="en" wait="60" hold="1" content="text/xml; charset=utf-8" ver="1.6" xmpp:version="1.0" xmlns:xmpp="urn:xmpp:xbosh"/>
[2013-04-11 08:11:05.493] [TRACE] [bosh.js:bosh_request_handler:235] - Processing Request
[2013-04-11 08:11:05.494] [TRACE] [bosh.js:process_bosh_request:150] - Session Creation
[2013-04-11 08:11:05.496] [TRACE] [session.js:Object.Session.reset_inactivity_timeout:543] - 5d14f41a-3f74-4b29-b22c-1cd63ae24e87 reset_inactivity_timeout - 80 sec
[2013-04-11 08:11:05.500] [TRACE] [session.js:Object.Session.add_held_http_connection:495] - 5d14f41a-3f74-4b29-b22c-1cd63ae24e87 add_held_http_connection - now holding 1 res obj
[2013-04-11 08:11:05.501] [TRACE] [xmpp-proxy-connector.js:Object.XMPPProxyConnector.stream_add:146] - 5d14f41a-3f74-4b29-b22c-1cd63ae24e87 a69c941a-847c-4d81-b444-4e13668bd2f9 stream_add
[2013-04-11 08:11:05.507] [TRACE] [lookup-service.js:try_connect_SRV_lookup:112] - try_connect_SRV_lookup - parallels-parallels-virtual-platform, 5222
[2013-04-11 08:11:05.509] [TRACE] [session.js:Object.Session.enqueue_bosh_response:861] - 5d14f41a-3f74-4b29-b22c-1cd63ae24e87 a69c941a-847c-4d81-b444-4e13668bd2f9
[2013-04-11 08:11:05.639] [TRACE] [lookup-service.js:Socket._on_socket_connect:91] - Connection to parallels-parallels-virtual-platform succeeded
[2013-04-11 08:11:05.640] [TRACE] [xmpp-proxy.js:XMPPProxy.dutil.copy._on_connect:270] - 5d14f41a-3f74-4b29-b22c-1cd63ae24e87 a69c941a-847c-4d81-b444-4e13668bd2f9 connected
[2013-04-11 08:11:05.645] [TRACE] [xmpp-proxy.js:XMPPProxy.dutil.copy.send:256] - 5d14f41a-3f74-4b29-b22c-1cd63ae24e87 a69c941a-847c-4d81-b444-4e13668bd2f9 Sent: <stream:stream xmlns:stream="http://etherx.jabber.org/streams" xmlns="jabber:client" to="parallels-parallels-virtual-platform" version="1.0">
[2013-04-11 08:11:05.646] [TRACE] [xmpp-proxy-connector.js:Object.<anonymous>:79] - 5d14f41a-3f74-4b29-b22c-1cd63ae24e87 a69c941a-847c-4d81-b444-4e13668bd2f9 _on_xmpp_proxy_connected - connected
[2013-04-11 08:11:05.648] [TRACE] [bosh.js:Object._on_stream_added:242] - 5d14f41a-3f74-4b29-b22c-1cd63ae24e87 a69c941a-847c-4d81-b444-4e13668bd2f9 stream-added
[2013-04-11 08:11:05.649] [TRACE] [lookup-service.js:Socket._on_socket_connect:91] - Connection to parallels-parallels-virtual-platform succeeded
[2013-04-11 08:11:05.655] [TRACE] [xmpp-proxy.js:XMPPProxy.dutil.copy._on_connect:270] - 5d14f41a-3f74-4b29-b22c-1cd63ae24e87 a69c941a-847c-4d81-b444-4e13668bd2f9 connected
[2013-04-11 08:11:05.658] [TRACE] [xmpp-proxy.js:XMPPProxy.dutil.copy.send:256] - 5d14f41a-3f74-4b29-b22c-1cd63ae24e87 a69c941a-847c-4d81-b444-4e13668bd2f9 Sent: <stream:stream xmlns:stream="http://etherx.jabber.org/streams" xmlns="jabber:client" to="parallels-parallels-virtual-platform" version="1.0">
[2013-04-11 08:11:05.659] [TRACE] [xmpp-proxy-connector.js:Object.<anonymous>:79] - 5d14f41a-3f74-4b29-b22c-1cd63ae24e87 a69c941a-847c-4d81-b444-4e13668bd2f9 _on_xmpp_proxy_connected - connected
[2013-04-11 08:11:05.660] [TRACE] [bosh.js:Object._on_stream_added:242] - 5d14f41a-3f74-4b29-b22c-1cd63ae24e87 a69c941a-847c-4d81-b444-4e13668bd2f9 stream-added
[2013-04-11 08:11:05.662] [DEBUG] [xmpp-proxy.js:XMPPProxy.dutil.copy._on_data:289] - 5d14f41a-3f74-4b29-b22c-1cd63ae24e87 a69c941a-847c-4d81-b444-4e13668bd2f9 RECD 638 bytes
[2013-04-11 08:11:05.663] [TRACE] [xmpp-proxy.js:XMPPProxy.dutil.copy._on_stream_start:303] - 5d14f41a-3f74-4b29-b22c-1cd63ae24e87 a69c941a-847c-4d81-b444-4e13668bd2f9 stream started
[2013-04-11 08:11:05.665] [TRACE] [xmpp-proxy.js:XMPPProxy.dutil.copy._on_stanza:162] - 5d14f41a-3f74-4b29-b22c-1cd63ae24e87 a69c941a-847c-4d81-b444-4e13668bd2f9 _on_stanza parsed: <stream:features><starttls xmlns="urn:ietf:params:xml:ns:xmpp-tls"/><mechanisms xmlns="urn:ietf:params:xml:ns:xmpp-sasl"><mechanism>SCRAM-SHA-1</mechanism><mechanism>DIGEST-MD5</mechanism><mechanism>PLAIN</mechanism></mechanisms><c xmlns="http://jabber.org... [188 more characters]
[2013-04-11 08:11:05.671] [TRACE] [xmpp-proxy.js:XMPPProxy.dutil.copy._on_stanza:187] - 5d14f41a-3f74-4b29-b22c-1cd63ae24e87 a69c941a-847c-4d81-b444-4e13668bd2f9 _on_stanza starttls requested
[2013-04-11 08:11:05.676] [TRACE] [xmpp-proxy.js:XMPPProxy.dutil.copy._on_stanza:192] - 5d14f41a-3f74-4b29-b22c-1cd63ae24e87 a69c941a-847c-4d81-b444-4e13668bd2f9 Writing out starttls
[2013-04-11 08:11:05.677] [TRACE] [xmpp-proxy.js:XMPPProxy.dutil.copy.send:256] - 5d14f41a-3f74-4b29-b22c-1cd63ae24e87 a69c941a-847c-4d81-b444-4e13668bd2f9 Sent: <starttls xmlns="urn:ietf:params:xml:ns:xmpp-tls"/>
[2013-04-11 08:12:05.500] [TRACE] [session.js:Object.Session._send_no_requeue:893] - 5d14f41a-3f74-4b29-b22c-1cd63ae24e87 ro: true
[2013-04-11 08:12:05.501] [TRACE] [session.js:Object.Session._send_no_requeue:898] - 5d14f41a-3f74-4b29-b22c-1cd63ae24e87 ro.rid: 3580127578, this.rid: 3580127578
[2013-04-11 08:12:05.505] [DEBUG] [response.js:Object.Response.send_response:85] - 5d14f41a-3f74-4b29-b22c-1cd63ae24e87 SENT(3580127578): <body xmlns="http://jabber.org/protocol/httpbind" message="Timed out"/>
[2013-04-11 08:12:05.509] [TRACE] [http-server.js:Server.http_request_handler:315] - Processing POST request at location: /http-bind
[2013-04-11 08:12:05.510] [DEBUG] [http-server.js:_unwrapped_on_end_callback:135] - RECD: <body rid="3580127579" xmlns="http://jabber.org/protocol/httpbind"/>
[2013-04-11 08:12:05.512] [TRACE] [bosh.js:bosh_request_handler:235] - Processing Request
[2013-04-11 08:12:05.513] [TRACE] [bosh.js:process_bosh_request:171] - No_Session_ID Invalid Session
[2013-04-11 08:12:05.513] [TRACE] [session.js:Object.SessionStore.send_invalid_session_terminate_response:1217] - Sending invalid sid
[2013-04-11 08:12:05.541] [DEBUG] [response.js:Object.Response.send_response:85] - invalid-sid SENT(null): <body xmlns="http://jabber.org/protocol/httpbind" condition="item-not-found" message="Invalid session ID" type="terminate"/>
[2013-04-11 08:12:05.651] [INFO] [xmpp-proxy.js:XMPPProxy.dutil.copy._on_close:334] - 5d14f41a-3f74-4b29-b22c-1cd63ae24e87 a69c941a-847c-4d81-b444-4e13668bd2f9 error: false
[2013-04-11 08:12:05.652] [INFO] [xmpp-proxy.js:XMPPProxy.dutil.copy._close_connection:328] - 5d14f41a-3f74-4b29-b22c-1cd63ae24e87 a69c941a-847c-4d81-b444-4e13668bd2f9 error: null
[2013-04-11 08:12:05.654] [INFO] [xmpp-proxy-connector.js:Object._on_xmpp_proxy_close:59] - 5d14f41a-3f74-4b29-b22c-1cd63ae24e87 a69c941a-847c-4d81-b444-4e13668bd2f9 - terminate stream
[2013-04-11 08:12:05.656] [TRACE] [session.js:Object.Session.enqueue_bosh_response:861] - 5d14f41a-3f74-4b29-b22c-1cd63ae24e87 a69c941a-847c-4d81-b444-4e13668bd2f9
[2013-04-11 08:12:05.658] [TRACE] [session.js:Object.Session.get_response_object:723] - 5d14f41a-3f74-4b29-b22c-1cd63ae24e87 get_response_object - holding 0 ro
[2013-04-11 08:12:05.659] [INFO] [session.js:Object.Session.send_terminate_response:604] - 5d14f41a-3f74-4b29-b22c-1cd63ae24e87 send_terminate_response - ro: false, condition: no-condition
[2013-04-11 08:12:05.661] [TRACE] [session.js:Object.Session._send_no_requeue:893] - 5d14f41a-3f74-4b29-b22c-1cd63ae24e87 ro: false
[2013-04-11 08:12:05.666] [TRACE] [session.js:Object.Session.get_response_object:723] - 5d14f41a-3f74-4b29-b22c-1cd63ae24e87 get_response_object - holding 0 ro
[2013-04-11 08:12:05.667] [TRACE] [session.js:Object.Session.send_pending_responses:794] - 5d14f41a-3f74-4b29-b22c-1cd63ae24e87 pending.length: 0, Holding 0 response objects
dhruvbird commented 11 years ago

That's strange.

@kmtsar Can you check if the output of grep -i "version" node_modules/dns-srv/package.json (from your node-xmpp-bosh checkout directory is "version": "0.1.0",.

@satyamshekhar I am trying locally, and it seems to be working fine with gmail.com, but gets stuck after sending <starttls/> to jabber.org. Any idea what could be happening? I tried turning off TLS for jabber.org, but it's now stuck at AUTH. You think we should be using the new TLS API in node.js? http://nodejs.org/api/tls.html#tls_tls_connect_options_callback

I'm skeptical, since it's working with gmail.com.

Mingism commented 11 years ago

@dhruvbird yeah i made sure i had the new version already, because I made a mistake initially. But I ran the grep anyway and it returned:

  "version": "0.1.0",

But just for my understanding, how does NXB know to which host and to which port it should connect, because these settings cannot be set in the config file. So I assume it is extracting the hostname from the JID and using the default port (5222)?

dhruvbird commented 11 years ago

@kmtsar Thanks for confirming the version. Can you check if you can connect to a gmail.com account - since that's what seems to be working here. jabber.org accounts not work. I'll also try with a lesser node.js version and get back to you.

w.r.t. knowing what port to connect to, NXB tries various approaches like SRV record lookup, and A record lookup followed by a good guess (which is the hard-coded port 5222 that you mentioned). The exact logic is a bit convoluted and copied from another project: node-xmpp. You can find it here: https://github.com/dhruvbird/dns-srv/blob/master/srv.js

Mingism commented 11 years ago

@dhruvbird Yes, indeed a gmail account works correctly.

If it is of any help:

parallels@parallels-Parallels-Virtual-Platform:~$ node -v v0.10.2

satyamshekhar commented 11 years ago

@dhruvbird I will try running it tonight.

dhruvbird commented 11 years ago

Works with node v0.8.11 - seems to be a node.js issue - I haven't been following the ML, so I don't know what could have changed - any suggestions?

dhruvbird commented 11 years ago

Probably next thing to try would be to see if using the node.js TLS API works.

Update: Doesn't work with their tls.connect() API either. Posting on google groups: https://groups.google.com/forum/?fromgroups=#!topic/nodejs/qbX72V-NRvU

Mingism commented 11 years ago

This could be related? https://github.com/Flowdalic/asmack/issues/30

I checked the log of my ejabberd server and I do not see anything making a connection to it. I will investigate further after the weekend. Do you log the attempt where the NXB is trying to connect to the XMPP server?

dhruvbird commented 11 years ago

@kmtsar Thank for pulling out that issue - will go over it and see if it's relevant.

So, with pigdin=true, you are receiving data from the xmpp server. See

[2013-04-11 08:11:05.662] [DEBUG] [xmpp-proxy.js:XMPPProxy.dutil.copy._on_data:289] - 5d14f41a-3f74-4b29-b22c-1cd63ae24e87 a69c941a-847c-4d81-b444-4e13668bd2f9 RECD 638 bytes

I would try using node v0.8.11 (if possible) and see if things are working with that version. Same git branch.

dhruvbird commented 11 years ago

It was an issue with the new EventEmitter implementation - fixed on current master. Please reopen if not fixed. Should work with node.js 0.10.2, 0.10.3 and 0.10.4.