Problem with XMPP server

Question

Some of the users of my app are reporting problem when connecting on XMPP server. The problem seems that the server sometimes send presence before the session is established.

We send:

* iq xmlns='jabber:client' type='set' id='532517604863'
    * session xmlns='urn:ietf:params:xml:ns:xmpp-session'

then we receive:

* presence xmlns='jabber:client' from='[e-mail]/{ee7ebd39-4c8c-4799-913b-d636487a42a8}' to='[e-mail]/{ff634bd3-6142-422a-9f2a-7aec158a9b38}'
    * show
        "away"
    * status
        "say cheese"
    * x xmlns='vcard-temp:x:update'
        * photo

But we should first get result for the session, like

* iq xmlns='jabber:client' id='532517604863' type='result'
    * session xmlns='urn:ietf:params:xml:ns:xmpp-session'

So our client disconnect with error 'Session iq response invalid'.

What's weird is that it never happened to me, only 2 of our users reported that issue so far.

Answer 1

Hi Xavier,

I'll investigate this and see what I can find out.

Thanks,

Bill

Answer 2

Any news on this? I got a few new users reporting this...

Here is more complete logs:

wocky-DEBUG: 07/05/12 14:30:17.278251: _end_element_ns: Received stanza
* success xmlns='urn:ietf:params:xml:ns:xmpp-sasl'
gabble/authentication-DEBUG: 07/05/12 14:30:17.278352: gabble_server_sasl_channel_success_async (server-sasl-channel.c:886): 
gabble/authentication-DEBUG: 07/05/12 14:30:17.278959: gabble_server_sasl_channel_accept_sasl (server-sasl-channel.c:656): client has accepted server's success
wocky-DEBUG: 07/05/12 14:30:17.279058: auth_succeeded: wocky-sasl-auth.c:245: Authentication succeeded
wocky-DEBUG: 07/05/12 14:30:17.279118: wocky_xmpp_reader_reset: wocky-xmpp-reader.c:775: Resetting the xmpp reader
wocky-DEBUG: 07/05/12 14:30:17.279203: wocky_xmpp_writer_stream_open: wocky-xmpp-writer.c:298: Writing stream opening: 
<stream:stream to="messenger.live.com" version="1.0" xmlns="jabber:client" xmlns:stream="http://etherx.jabber.org/streams">
gabble/authentication-DEBUG: 07/05/12 14:30:17.279596: gabble_server_sasl_channel_close (server-sasl-channel.c:965): called on 0x93c3f0
wocky-DEBUG: 07/05/12 14:30:17.364993: handle_stream_open: wocky-xmpp-reader.c:431: Received stream opening: stream, prefix: stream, uri: http://etherx.jabber.org/streams
wocky-DEBUG: 07/05/12 14:30:17.365082: handle_stream_open: wocky-xmpp-reader.c:450: Stream opening attribute: from = 'messenger.live.com' (prefix: <no prefix="">, uri: <no uri="">)
wocky-DEBUG: 07/05/12 14:30:17.365134: handle_stream_open: wocky-xmpp-reader.c:450: Stream opening attribute: version = '1.0' (prefix: <no prefix="">, uri: <no uri="">)
wocky-DEBUG: 07/05/12 14:30:17.365176: handle_stream_open: wocky-xmpp-reader.c:450: Stream opening attribute: id = '174673' (prefix: <no prefix="">, uri: <no uri="">)
wocky-DEBUG: 07/05/12 14:30:17.465327: _end_element_ns: Received stanza
* features xmlns='http://etherx.jabber.org/streams'
    * bind xmlns='urn:ietf:params:xml:ns:xmpp-bind'
    * session xmlns='urn:ietf:params:xml:ns:xmpp-session'
    * sub xmlns='urn:xmpp:features:pre-approval'
wocky-DEBUG: 07/05/12 14:30:17.465470: _write_node_tree: Serializing tree:
* iq xmlns='jabber:client' type='set' id='4112465428'
    * bind xmlns='urn:ietf:params:xml:ns:xmpp-bind'
        * resource
            "f04c8ec5"
wocky-DEBUG: 07/05/12 14:30:17.553107: _end_element_ns: Received stanza
* iq xmlns='jabber:client' id='4112465428' type='result'
    * bind xmlns='urn:ietf:params:xml:ns:xmpp-bind'
        * jid
            "[e-mail]/{27543b97-5328-4a63-9a3d-d8fb3bd57cbb}"
wocky-DEBUG: 07/05/12 14:30:17.553251: _write_node_tree: Serializing tree:
* iq xmlns='jabber:client' type='set' id='528569553214'
    * session xmlns='urn:ietf:params:xml:ns:xmpp-session'
wocky-DEBUG: 07/05/12 14:30:17.636331: _end_element_ns: Received stanza
* presence xmlns='jabber:client' from='[e-mail]/{98b78c2c-604c-6c2d-4ebc-630da4217480}' to='[e-mail]/{27543b97-5328-4a63-9a3d-d8fb3bd57cbb}'
    * show
        "chat"
    * x xmlns='vcard-temp:x:update'
        * photo
gabble/connection-DEBUG: 07/05/12 14:30:17.636514: connector_error_disconnect (connection.c:1772): connection failed: WOCKY_CONNECTOR_ERROR_SESSION_FAILED (#14): Session iq response invalid</no></no></no></no></no></no></stream:stream>

Answer 3

Hi,

I can reproduce the problem if I connect to WLM using the standard WLM protocol from somewhere else. If I disconnect my other clients, then the XMPP gateway behaves properly, so I guess it's the server sending me the presence of the other clients (resources).

Olivier

Answer 4

Im also facing the same problem.

From logs I can see that the server is performing session binding without it is being requested by the client. Please see this:

<stream:features xmlns:stream="http://etherx.jabber.org/streams"><bind xmlns="urn:ietf:params:xml:ns:xmpp-bind"/><session xmlns="urn:ietf:params:xml:ns:xmpp-
session"/><sub xmlns="urn:xmpp:features:pre-approval"/></stream:features> 

I got above packet without sending a session bind packet.

Answer 5

Please reply.

-Amit Goyal

Answer 6

From RFC 3921 (http://xmpp.org/rfcs/rfc3921.html), section 3:

If a server supports sessions, it MUST include a <session/> element qualified by the 'urn:ietf:params:xml:ns:xmpp-session' namespace in the stream features it advertises to a client after the completion of stream authentication as defined in [XMPP‑CORE].

The session sub-element in <stream:features> is not a reply to a bind request from the client. It is a notification to the client that bind requests are now supported, since SASL negotiation has finished.

The issue reported earlier in the thread seems to be that a session response is not being received, or that presence is preceding the session response. If this is not the case, please clarify.

Thanks,

Bill

Answer 7

Exactly

Answer 8

Hi Bill,

Yes, issue is exactly same as you have mentioned.

I was trying to highlight the cause of the problem, but it seems that I was wrong.

I was thinking that the MSN is doing the session establishment himself without it is being requested by the client. Actually I was confused with the element "<sub xmlns="urn:xmpp:features:pre-approval"/>" in the stream feature response. I thought that the element signifies that the server has already established the session on behalf of the client. But as per your explanation it looks like that is not the case.

Btw, I would like to know that what is the significance of  the element "<sub xmlns="urn:xmpp:features:pre-approval"/>" in stream feature response.

P.S. sorry guys if I have asked the question on wrong thread.

Thanks,

Amit Goyal

Answer 9

I can now reproduce that bug: just have the account connected using pidgin (probably any client is fine) then connect the same account with XMPP and it will receive presences before session is established.

Answer 10

I appreciate all the information on this thread, it's been useful.

I don't have a date on which you'll see a change on the service, but I am working through a fix for the issue.

Thanks,

Bill

Answer 11

How long time will it take to fix it or is already close to releasing a fix?<style>img, #cubbies-overlay{ -moz-transition-property: margin, box-shadow, z-index; -moz-transition-duration: 0.1s; -webkit-transition-property: margin, box-shadow, z-index; -webkit-transition-duration: 0.1s; } .cubbies-selected{ z-index: 9999; box-shadow: 3px 3px 8px -1px blue !important; cursor: pointer !important; margin: -3px 3px 3px -3px; } .cubbies-selected:active{ box-shadow: 2px 2px 5px -1px darkblue !important; margin: -1px 1px 1px -1px; } #cubbies-overlay{ position: fixed; z-index: 9999; bottom: 30px; left: 30px; box-shadow: 0 2px 3px rgba(0,0,0,0.8); border: none; } #cubbies-overlay:hover{ box-shadow: 0 2px 3px rgb(0,0,0); }</style>

Answer 12

Hi Bruno,

As of right now I'm receiving self and buddy presence only after a session stanza exchange has been performed. If you are seeing the behavior described in this thread (presence for buddies received before stanza negotiation ends), please email any logs you have from your client(s) to bgarrett (at) Microsoft (dot) com, and I can review them.

Thanks,

Bill

Answer 13

Does this means you fixed the issue, or you couldn't reproduce it?

Answer 14

It means that I've fixed the issue that I discovered, and I want to make sure there aren't other scenarios that I'm not aware of where it might also happen.

Thanks,

Bill

Answer 15

My app does not support see-other-host yet, so I was unable to verify if the fix works...

However, I just finished the support for see-other-host in my dev branch, and I got this bug again! There must be a race condition somewhere in your server implementation. Note that it does not always happen, sometimes it succeed after a few reconnect attempts.

Thanks for your work anyway ;-)

Answer 16

Hi Xavier,

If you have any client logs you're able to send me, it'd help a great deal. You can email bgarrett (at) Microsoft (dot) com if so.

Thanks,

Bill

Answer 17

I've sent the full logs of a failed AND successful connection attempts to your email. I hope it will help :)

Answer 18

I received the logs and am reviewing them. This is indeed a different scenario. I'll update this thread once I have more information.

Thanks,

Bill

Answer 19

any progress on this? It still happens a lot here...

Answer 20

Hi Xavier,

I can't commit to a particular release date for a fix, but I have identified the issue. I will keep you updated once there's a change in status.

Thanks,

Bill

Answer 21

Hi Xavier,

A change was made to correct this condition which should appear in the next release of Messenger.

Thanks,

Bill