Could not reconnect using Smack 4.2-beta2, Stream Management and Ejabberd

Smack Smack Dev
1

Hello!

Sometimes I’m having problem on reconnecting using existing XmppConnection. Here is the XMPP log:

02:22:26 PM SENT (0): <stream:stream xmlns='jabber:client' to='example.com' xmlns:stream='http://etherx.jabber.org/streams' version='1.0' from='username@example.com' xml:lang='en'>
02:22:26 PM RECV (0): <?xml version='1.0'?><stream:stream xmlns='jabber:client' xmlns:stream='http://etherx.jabber.org/streams' id='17455584410506089384' from='example.com' version='1.0' xml:lang='en'>
<stream:features>
  <c xmlns='http://jabber.org/protocol/caps' hash='sha-1' node='http://www.process-one.net/en/ejabberd/' ver='zYbfeEEY8mBWluDWrbpsxRBZ1Yo='/>
  <starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'/>
  <mechanisms xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
  <mechanism>PLAIN</mechanism>
  <mechanism>X-OAUTH2</mechanism>
  </mechanisms>
</stream:features>
02:22:26 PM SENT (0): <starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'></starttls>
02:22:26 PM RECV (0): <proceed xmlns='urn:ietf:params:xml:ns:xmpp-tls'/>
02:22:27 PM SENT (0): <stream:stream xmlns='jabber:client' to='example.com' xmlns:stream='http://etherx.jabber.org/streams' version='1.0' from='username@example.com' id='17455584410506089384' xml:lang='en'>
02:22:27 PM RECV (0): <?xml version='1.0'?><stream:stream xmlns='jabber:client' xmlns:stream='http://etherx.jabber.org/streams' id='10835831553119613618' from='example.com' version='1.0' xml:lang='en'>
02:22:27 PM RECV (0): <stream:features>
  <c xmlns='http://jabber.org/protocol/caps' hash='sha-1' node='http://www.process-one.net/en/ejabberd/' ver='zYbfeEEY8mBWluDWrbpsxRBZ1Yo='/>
  <mechanisms xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
  <mechanism>PLAIN</mechanism>
  <mechanism>X-OAUTH2</mechanism>
  </mechanisms>
</stream:features>
02:22:27 PM SENT (0): <auth xmlns='urn:ietf:params:xml:ns:xmpp-sasl' mechanism='PLAIN'>AGdyaWdvcnkuZmVkb3JvdgAwZTAyYWIxZC1jY2RkLTQ1YWItYWZiNy1jMzFhODcyOWE0OTU=</auth>
02:22:28 PM RECV (0): <success xmlns='urn:ietf:params:xml:ns:xmpp-sasl'/>
02:22:28 PM SENT (0): <stream:stream xmlns='jabber:client' to='example.com' xmlns:stream='http://etherx.jabber.org/streams' version='1.0' from='username@example.com' id='10835831553119613618' <xml:langresume='en' xmlns='urn:xmpp:sm:3>' 02:22:28 PM SENT (0): h='215' previd='g2gCbQAAACMxNDM4OTc5OTMwNTM3MjgwMjE0MTQ3NzU2MDAxNDg0ODc2MGgDYgAABcViAAiLjGIAB6bM'/>
02:22:28 PM RECV (0): <?xml version='1.0'?><stream:stream xmlns='jabber:client' xmlns:stream='http://etherx.jabber.org/streams' id='7968936995629032410' from='example.com' version='1.0'>
02:22:28 PM RECV (0): <stream:error><xml-not-well-formed xmlns='urn:ietf:params:xml:ns:xmpp-streams'></xml-not-well-formed></stream:error>
10-27 14:22:33.025 W/AbstractXMPPConnection: Connection XMPPTCPConnection[username@example.com/14389799305372802141477560014848760] (0) closed with error
                                             java.lang.IllegalStateException: Could not transform string 'xml_not_well_formed' to XMPPErrorCondition
                                                 at org.jivesoftware.smack.packet.StreamError$Condition.fromString(StreamError.java:194)
                                                 at org.jivesoftware.smack.util.PacketParserUtils.parseStreamError(PacketParserUtils.java:819)
                                                 at org.jivesoftware.smack.tcp.XMPPTCPConnection$PacketReader.parsePackets(XMPPTCPConnection.java:1019)
                                                 at org.jivesoftware.smack.tcp.XMPPTCPConnection$PacketReader.access$300(XMPPTCPConnection.java:960)
                                                 at org.jivesoftware.smack.tcp.XMPPTCPConnection$PacketReader$1.run(XMPPTCPConnection.java:975)
                                                 at java.lang.Thread.run(Thread.java:761)
                                              Caused by: java.lang.IllegalArgumentException: No enum constant org.jivesoftware.smack.packet.StreamError.Condition.xml_not_well_formed
                                                 at java.lang.Enum.valueOf(Enum.java:254)
                                                 at org.jivesoftware.smack.packet.StreamError$Condition.valueOf(StreamError.java:156)
                                                 at org.jivesoftware.smack.packet.StreamError$Condition.fromString(StreamError.java:192)
                                                 at org.jivesoftware.smack.util.PacketParserUtils.parseStreamError(PacketParserUtils.java:819)                                                  at org.jivesoftware.smack.tcp.XMPPTCPConnection$PacketReader.parsePackets(XMPPTCPConnection.java:1019)                                                  at org.jivesoftware.smack.tcp.XMPPTCPConnection$PacketReader.access$300(XMPPTCPConnection.java:960)                                                  at org.jivesoftware.smack.tcp.XMPPTCPConnection$PacketReader$1.run(XMPPTCPConnection.java:975)                                                  at java.lang.Thread.run(Thread.java:761)

It looks like more than one thread writing to stream, but I use single one for Smack connection. Is it possible to have problem inside of Smack?

2

Thanks for reporting. At first I thought that this looks like an issue caused an re-used deflate dictionary, but you don’t use compression (or do you?). It certainly could be a synchronization issue inside of Smack. Unfortunately those are often hard to hunt down. Any help is appreciated, e.g. if you observe something which could be related or found an potential synchronization issue in Smack’s code.

3

Isn’t Smack’s PacketWriter single-threaded? Afaik there’s a BlockingQueue which is processed by one thread only. If this is the case it can’t be a multi-threading issue, unless of course the stream header is not written by the same thread as the stream elements.

Btw: Ejabberd still using the outdated and deprecated xml-not-well-formed from RFC 3920!? Shame…

4

I’ve looked a bit into it. It appears that

<stream:stream xmlns=‘jabber:client’ to=‘example.com’ xmlns:stream=‘http://etherx.jabber.org/streams’ version=‘1.0’ from=‘username@example.com’ id=‘10835831553119613618’

<xml:langresumexml:langresume=‘en’ xmlns=‘urn:xmpp:sm:3>’

is a stream open tag send after SASL and a SM intermixed. I can’t tell how this could have happen, since both elements are put on the wire after being serialized in the writer’s queue (at least that is what should have happened).

5

I am running into the same issue on Smack 4.2-rc3

It is strange though. After a handful of re-connection attempts, eventually it will reconnect with correctly formatted xml.