powered by Jive Software

Smack ack 'h' (handled) count terminates the stream with OpenFire Server


#1

Hi; I am using Smack 4.2.0 in Android, connecting to an OpenFire server. When I enable stream management I occasionally get an error like this and the stream is terminated:

<stream:error xmlns:stream=“http://etherx.jabber.org/streams”>You acknowledged stanzas that we didn’t send. Your Ack h: 13, our last stanza: 10</stream:error></stream:stream>

When I check the logs and count the incoming stanzas, server seems to be right about this message. Here is a sample log which starts with a correct ack, and terminates with an incorrect one:


 SENT (0): <a xmlns='urn:xmpp:sm:3' h='22'/>
 SENT (0): <message to='myuser@mydomain.com/android' id='recpt-gWwsFh2w-5'><body>rcpt</body><receipt xmlns='com.hede/receipt' type='DISPLAYED'><msg-id>msg-QIxBgr4O-4</msg-id></receipt></message><r xmlns='urn:xmpp:sm:3'/>
 RECV (0): <a xmlns='urn:xmpp:sm:3' h='48' />
 RECV (0): <message to="myuser2@mydomain.com/android" id="0eNbz-387" from="myuser@mydomain.com/android"><active xmlns="http://jabber.org/protocol/chatstates"></active></message>
 RECV (0): <message to="myuser2@mydomain.com/android" id="0eNbz-388" from="myuser@mydomain.com/android"><composing xmlns="http://jabber.org/protocol/chatstates"></composing></message>
 RECV (0): <message to="myuser2@mydomain.com/android" id="0eNbz-389" from="myuser@mydomain.com/android"><active xmlns="http://jabber.org/protocol/chatstates"></active></message>
 RECV (0): <message to="myuser2@mydomain.com/android" id="msg-YjIHyzrr-5" type="chat" from="myuser@mydomain.com/android"><body>654</body></message>
 SENT (0): <message to='myuser@mydomain.com/android' id='recpt-iAmWfY9I-6'><body>rcpt</body><receipt xmlns='com.hede/receipt' type='DISPLAYED'><msg-id>msg-YjIHyzrr-5</msg-id></receipt></message><r xmlns='urn:xmpp:sm:3'/>
 RECV (0): <a xmlns='urn:xmpp:sm:3' h='49' />
 SENT (0): <message to='myuser@mydomain.com/android' id='nTQ28-117'><composing xmlns='http://jabber.org/protocol/chatstates'/></message><r xmlns='urn:xmpp:sm:3'/>
 RECV (0): <a xmlns='urn:xmpp:sm:3' h='50' />
 SENT (0): <message to='myuser@mydomain.com/android' id='nTQ28-118'><active xmlns='http://jabber.org/protocol/chatstates'/></message><r xmlns='urn:xmpp:sm:3'/>
 SENT (0): <message to='myuser@mydomain.com/android' id='msg-JsxaEHEm-3' type='chat'><body>Iv</body></message><r xmlns='urn:xmpp:sm:3'/>
 RECV (0): <a xmlns='urn:xmpp:sm:3' h='51' />
 RECV (0): <a xmlns='urn:xmpp:sm:3' h='52' />
 RECV (0): <message to="myuser2@mydomain.com/android" id="recpt-k4KQNSgz-7" from="myuser@mydomain.com/android"><body>rcpt</body><receipt xmlns="com.hede/receipt" type="DISPLAYED"><msg-id>msg-JsxaEHEm-3</msg-id></receipt></message>
 RECV (0): <r xmlns='urn:xmpp:sm:3' />
 SENT (0): <a xmlns='urn:xmpp:sm:3' h='29'/>
 RECV (0): <stream:error xmlns:stream="http://etherx.jabber.org/streams"><undefined-condition xmlns="urn:ietf:params:xml:ns:xmpp-streams"/><text xmlns="urn:ietf:params:xml:ns:xmpp-streams">You acknowledged stanzas that we didn't send. Your Ack h: 29, our last stanza: 27</text></stream:error></stream:stream>
 XMPPConnection closed due to an exception (XMPPTCPConnection[myuser2@mydomain.com/android] (0))

First ack is h=22 and after that there are 5 incoming message stanzas, hence the second one should have been 27, but it was 29.

There are a bunch of chat state messages (XEP-0085) in there too but I have no idea whether they should count as they have empty bodies and are supposed to be sort of transitient.

Can anybody guide me on this? Is there anything wrong with this log?

Best regards.


Server terminates client connection due to the client acknowledging a stanza that was not sent by the server
#2

Does that also happen with the latest released version of Smack (4.2.3)?

All stanzas count, irregadles of their content.


#3

Hi Flow;

I checked the recent commits and did not see anything mentioning stream management so I did not think new version might solve my issue. I will update, try and report back.

Best regards.


#4

Unfortunately I still encounter it with 4.2.3.

Just a question btw., are the SENT - RECV log lines serial/in order? I mean can we just look at an outgoing ack, lets say it’s h = 20, count 5 incoming stanzas in the logs from that point on, and can reliably say the next one will/has to be 25?

Best regards.


#5

The log may be out of order.
Afaik Recent Openfire has issues with StreamManagement, so it might in fact be an Openfire issue. Did you test your implementation against other servers too?


#6

Yes, there is also an ejabberd server. Actually i already tested with it after upgrading smack to latest version. I did not encounter the same issue, it is also configured to use stream management and i can see acks in the logs.

It may either mean this is an openfire issue or still a smack issue but handled gracefully by the other server, i am not sure. However now that you mention it, we recently updated openfire to a new version and i dont remember it happening before. Do you know the exact version that has stream management issues? Thanks btw.

Anyway; whether caused by smack or openfire or my implementation, i have to pinpoint it. The app i am working on is almost unusable in its current state because of these disconnects. I will also check openfire support forums.

Best regards.


#7

2 posts were merged into an existing topic: Terminating the connection on inconsistent Stream Management data


#9

It should be in-order, otherwise the logs would be pretty useless.

To be frank, it looks more like an client issue. But on the other hand, I haven’t received a bug report regarding Smack’s Stream Management functionality in a while. But the log we see is

SENT (0): <a xmlns='urn:xmpp:sm:3' h='22'/>
RECV (0): <message></message>
RECV (0): <message></message>
RECV (0): <message></message>
RECV (0): <message></message>
…
RECV (0): <message></message>
…
SENT (0): <a xmlns='urn:xmpp:sm:3' h='29'/>
RECV (0): <stream:error xmlns:stream="http://etherx.jabber.org/streams"><undefined-condition xmlns="urn:ietf:params:xml:ns:xmpp-streams"/><text xmlns="urn:ietf:params:xml:ns:xmpp-streams">You acknowledged stanzas that we didn't send. Your Ack h: 29, our last stanza: 27</text></stream:error></stream:stream>
 XMPPConnection closed due to an exception (XMPPTCPConnection[myuser2@mydomain.com/android] (0))

which clearly shows the server is right, indicating a client issue.


#10

Today I will capture a wireshark trace and count the incoming packets after
stream establishment. I can replicate the issue but sometimes it takes too
long a sequence, if i can get a short enough one it should be countable.
And that should make the issue clear. I will share my findings.

Best regards


#11

As an update to the issue; someone seems to have just posted this about the same problem:

If their analysis is correct, it looks like a bug on Openfire side. I am still going to capture a trace though.

Best regards.


#12

Maybe it would be helpful to have the logs before the h=‘22’, i.e. the whole log.

So that we can count all reveived stanzas, just in case something went out of order in the log.


#13

A post was split to a new topic: Terminating the connection on inconsistent Stream Management data


#14

Hi once again;

I was able to clearly reproduce the problem while capturing a trace. I am not including the whole trace but I have a better result image. Here is what I did: I filtered the follow tcp output by incoming packets, copied the whole xml into Eclipse to format it and then marked all the stanzas in the xml document and this is the result:

The error I got was: “You acknowledged stanzas that we didn’t send. Your Ack h: 72, our last stanza: 70” but as you can see there actually are 72 incoming stanzas from the first till the stream termination. I will escalate this issue to our server team and to Openfire side of the forums. I can also send the original trace if someone is interested or wants to verify my findings.

Some ambiguity remains though, why were my first logs sort of indicating an error on the client side? Maybe there was some inconsistency in logging but the evidence I gathered is enough to shift my focus to server side for now.

Thanks to everybody for their comments and help.


#15

This is very useful information, thanks. I’d love to see that trace. Clicking on the link that you provide gives me a “Request forbidden by administrative rules” error though. Can you make it available again please?


#16

Seeing same issue with Android/Smack 4.2.0 and Openfire 4.2.3. Did not see issue when we previously used Openfire 4.1.6
I have tried updating to Smack 4.2.3, still having same issue
We will have to roll back to earlier version of Openfire due to existing Smack clients in use, which have stream mgmt enabled.
Does anyone know which version of Openfire introduced this behavior?

I also have a 3rd party XMPP client (Mac/Adium) that seems to behave quite a bit better (maybe it does not use stream mgmt?), but has also had minimal disconnect issues including error message “XMPP stream header missing”

I have tried to disable use of stream mgmt in Smack 4.2.3, and it seems to behave much better. But I may still have disconnect issues (much less frequently) which I need to review further

OpenFire/Server log

2018.03.28 11:41:02 WARN [socket_c2s-thread-3]: class org.jivesoftware.openfire.streammanagement.StreamManager[174.110.53.240] - Closing client session. Client acknowledges stanzas that we didn’t send! Client Ack h: 726, our last stanza: 721, affected session: org.jivesoftware.openfire.session.LocalClientSession@45e4880a status: 3 address: byoung@mytest.net/ANDROID-355301074232615 id: 8fz7b4mbfn presence:

Have also seen this variant in Openfire log

2018.03.28 13:14:49 ERROR [socket_c2s-thread-2]: org.jivesoftware.openfire.nio.ConnectionHandler - Closing connection due to error while processing message:

Smack/client error log
Often I see no error client side. The client continues to think it is still connected to Openfire, though it is not. But once I did capture this stack in the Android logcat

03-26 11:08:08.164 21274-26352/com.atakmap.app I/System.out: 11:08:08 RECV (2): <stream:error xmlns:stream=“http://etherx.jabber.org/streams”>You acknowledged stanzas that we didn’t send. Your Ack h: 143, our last stanza: 140</stream:error>
03-26 11:08:08.164 21274-26352/com.atakmap.app W/AbstractXMPPConnection: Connection XMPPTCPConnection[byoung@mytest.net/ANDROID-355301074232615] (2) closed with error
java.lang.IllegalStateException: Could not transform string ‘undefined_condition’ to XMPPErrorCondition
at org.jivesoftware.smack.packet.StreamError$Condition.fromString(StreamError.java:194)
at org.jivesoftware.smack.util.PacketParserUtils.parseStreamError(PacketParserUtils.java:820)
at org.jivesoftware.smack.tcp.XMPPTCPConnection$PacketReader.parsePackets(XMPPTCPConnection.java:1040)
at org.jivesoftware.smack.tcp.XMPPTCPConnection$PacketReader.access$300(XMPPTCPConnection.java:980)
at org.jivesoftware.smack.tcp.XMPPTCPConnection$PacketReader$1.run(XMPPTCPConnection.java:996)
at java.lang.Thread.run(Thread.java:818)
Caused by: java.lang.IllegalArgumentException: undefined_condition is not a constant in org.jivesoftware.smack.packet.StreamError$Condition
at java.lang.Enum.valueOf(Enum.java:200)
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:820)
at org.jivesoftware.smack.tcp.XMPPTCPConnection$PacketReader.parsePackets(XMPPTCPConnection.java:1040)
at org.jivesoftware.smack.tcp.XMPPTCPConnection$PacketReader.access$300(XMPPTCPConnection.java:980)
at org.jivesoftware.smack.tcp.XMPPTCPConnection$PacketReader$1.run(XMPPTCPConnection.java:996)
at java.lang.Thread.run(Thread.java:818)


#17

You could also simply disable stream management on server side, avoiding downgrading Openfire…


#18

Was having the same issue so I edited the below value:

stream.management.active false

Everything is working okay now:)