Bug: First stanza acknowledgement wrong packet ID

andrejvanderzee · January 29, 2015, 2:25pm

Hi,

The first message send to a chat has a mismatched packet ID when packet is intercepted by an StanzaAcknowledgedListener. After the first packet, everything looks as expected.

SENT (0): Some text82f9088beeb64f3aa7d6336f05cb5f81@localhost

SENT (0):

RECV (0):

StanzaAcknowledgedListener processPacket() packet ID: 31q8Y-5

SENT (0): Some text82f9088beeb64f3aa7d6336f05cb5f81@localhost

SENT (0):

RECV (0):

StanzaAcknowledgedListener processPacket() packet ID: 31q8Y-12

SENT (0): Some text82f9088beeb64f3aa7d6336f05cb5f81@localhost

SENT (0):

RECV (0):

StanzaAcknowledgedListener processPacket() packet ID: 31q8Y-13

Cheers,
Andrej

andrejvanderzee · January 30, 2015, 9:49am

In beta2-SNAPSHOT the behaviour is a bit different. For the first chat message I receive three ACKs:

SENT (0): hhhhhh7154a5d8af3e4221976d374b2f05e4c1@localho st

processPacket ACK: rm2mi-5

processPacket ACK: rm2mi-6

processPacket ACK: rm2mi-13

After that it behaves as I would expect.

When I register for the specific packet ID, the processPacket() callback is not even called.

Flow · January 30, 2015, 10:32am

Is this possible after a (failed) stream resumption? Could you provide more context (e.g. more XMPP traces, especially from the very first stream open).

It could be that you get the ack’s because -5, -6 are resend after a successive login because they weren’t ack’ed before.

Could you set a breakpoint just before the stanza id ack listener should be called to see why it’s not called?

andrejvanderzee · February 3, 2015, 7:50am

Hi,

Sorry for the late reply.

I looks like the addStanzaAcknowledgedListener callbacks are not called for the fist two packets until the first chat packet is ack’ed. See the last three lines in the log below.

When I register for the specific packet ID, processPacket() callback is not even called.

I am using the snapshot release of 2015-01-28. Unfortunately I do not know how to easily use the sources-jar inside Android Studio and therefor I am not able to set breakpoints (I am using the jar with the compiled sources).

Thanks,
Andrej

SENT (0): <stream:stream xmlns=‘jabber:client’ to=‘localhost’ xmlns:stream=‘http://etherx.jabber.org/streams’ version=‘1.0’ from=‘38d0c0e8cfd24522835db7002e65a959@localhost’ xml:lang=‘en’>

RECV (0): <?xml version='1.0'?><stream:stream xmlns=‘jabber:client’ xmlns:stream=‘http://etherx.jabber.org/streams’ id=‘572510457’ from=‘localhost’ version=‘1.0’ xml:lang=‘en’>

RECV (0): stream:featuresDIGEST-MD5SCRAM-SHA-1PLAIN<register xmlns='http://jabber.org/features/iq-register’/></stream:features>

SENT (0): biwsbj0zOGQwYzBlOGNmZDI0NTIyODM1ZGI3MDAyZTY1YTk1OSxyPUF iQGZPLjBWNWF+fiNVfSYna2c5LU46XGRZUVI9Zil2

RECV (0): cj1BYkBmTy4wVjVhfn4jVX0mJ2tnOS1OOlxkWV FSPWYpdndxUE92d2hoLzJ6K2hVL3p6QU5qbHc9PSxzPW1xeGdrakVxRVpvb2F2K3hyNDg3MHc9PSxpPT QwOTY=

SENT (0): Yz1iaXdzLHI9QWJAZk8uMFY1YX5+I1V9JidrZz ktTjpcZFlRUj1mKXZ3cVBPdndoaC8yeitoVS96ekFOamx3PT0scD1qSzZxRUprR3EzMzJSZkQ3VlkyL0 d0UXBrVGs9

RECV (0): dj0zcTF0djJMU2E1QU1tR1JnaytGNnh6K0lsM2 c9

SENT (0): <stream:stream xmlns=‘jabber:client’ to=‘localhost’ xmlns:stream=‘http://etherx.jabber.org/streams’ version=‘1.0’ from=‘38d0c0e8cfd24522835db7002e65a959@localhost’ id=‘572510457’ xml:lang=‘en’>

Last login: Mon Feb 2 19:26:44 on ttys000

matthijss-mbp:~ andrej$ vim /tmp/bla.txt

matthijss-mbp:~ andrej$ cat /tmp/bla.txt

SENT (0): <stream:stream xmlns=‘jabber:client’ to=‘localhost’ xmlns:stream=‘http://etherx.jabber.org/streams’ version=‘1.0’ from=‘38d0c0e8cfd24522835db7002e65a959@localhost’ xml:lang=‘en’>

RECV (0): <?xml version='1.0'?><stream:stream xmlns=‘jabber:client’ xmlns:stream=‘http://etherx.jabber.org/streams’ id=‘572510457’ from=‘localhost’ version=‘1.0’ xml:lang=‘en’>

RECV (0): stream:featuresDIGEST-MD5SCRAM-SHA-1PLAIN<register xmlns='http://jabber.org/features/iq-register’/></stream:features>

SENT (0): biwsbj0zOGQwYzBlOGNmZDI0NTIyODM1ZGI3MDAyZTY1YTk1OSxyPUF iQGZPLjBWNWF+fiNVfSYna2c5LU46XGRZUVI9Zil2

RECV (0): cj1BYkBmTy4wVjVhfn4jVX0mJ2tnOS1OOlxkWV FSPWYpdndxUE92d2hoLzJ6K2hVL3p6QU5qbHc9PSxzPW1xeGdrakVxRVpvb2F2K3hyNDg3MHc9PSxpPT QwOTY=

SENT (0): Yz1iaXdzLHI9QWJAZk8uMFY1YX5+I1V9JidrZz ktTjpcZFlRUj1mKXZ3cVBPdndoaC8yeitoVS96ekFOamx3PT0scD1qSzZxRUprR3EzMzJSZkQ3VlkyL0 d0UXBrVGs9

RECV (0): dj0zcTF0djJMU2E1QU1tR1JnaytGNnh6K0lsM2 c9

SENT (0): <stream:stream xmlns=‘jabber:client’ to=‘localhost’ xmlns:stream=‘http://etherx.jabber.org/streams’ version=‘1.0’ from=‘38d0c0e8cfd24522835db7002e65a959@localhost’ id=‘572510457’ xml:lang=‘en’>

RECV (0): <?xml version='1.0'?><stream:stream xmlns=‘jabber:client’ xmlns:stream=‘http://etherx.jabber.org/streams’ id=‘2594809415’ from=‘localhost’ version=‘1.0’ xml:lang=‘en’>stream:features<register xmlns='http://jabber.org/features/iq-register’/></stream:features>

SENT (0): android/38a332ee3de6e61a</re source>

RECV (0): 38d0c0e8cfd24522835db7002e65a959@ localhost/android/38a332ee3de6e61a

SENT (0):

RECV (0):

SENT (0):

RECV (0):

User logged (0): 38d0c0e8cfd24522835db7002e65a959@localhost:5222/android/38a332ee3de6e61a

XMPPConnection authenticated (0)

SENT (0):

RECV (0):

SENT (0):

RECV (0):

SENT (0):

SENT (0): ABC

7154a5d8af3e4221976d374b2f05e4c1

SENT (0):

RECV (0):

processPacket bPaws-6

processPacket bPaws-7

processPacket chat_message_ack_prefix_workaround_2

Flow · February 3, 2015, 9:07am

Unfortunately I do not know how to easily use the sources-jar inside Android Studio and therefor I am not able to set breakpoints (I am using the jar with the compiled sources)
I recommend researching how this can be done (if it can be done at all). Otherwise you won’t be able to determine the cause of your issues. I try to avoid using Android Studio, so I can’t tell you how to debug with source artifacts, sorry. But i’ve heard that it should be possible.

andrejvanderzee · February 3, 2015, 9:19am

Yes I agree totally with your comments. If I would only have the time… For now I am waiting for the beta2 release, unless I will have time left by the end of the week.

Nevertheless, the SMACK log should provide you enough information to acknowledge the current behaviour is incorrect. The ACK listeners for the following packets:

Are only called after the first chat packet is sent:

ABC

7154a5d8af3e4221976d374b2f05e4c1

Moreover, the ACK listeners by packet ID are not called at all.

Flow · February 3, 2015, 10:56am

Nevertheless, the SMACK log should provide you enough information to acknowledge the current behaviour is incorrect.
No it appears to be correct to me (besides the thing that the listeners for the stanza ID are not called at all): The first ack we receive from the server is received after you send the message. And if there is no ack received, then there is nothing to acknowledge.

You may want to install a “request ack predicate” that suits your needs: Index of /smack/dailybuilds/javadoc/org/jivesoftware /smack/tcp/XMPPTCPConnection.html#addReq…

So you are still invited to debug why the stanza id acked listeners are not called, as I see no reason looking at the relevant code why they should not be called (still can’t rule out that I missed something).