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:
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?
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.
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?
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?
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.
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.
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.
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.
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?
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:
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)
?