Smack 4.2.0-rc3: VCardManager#loadVCard reported timeout even VCard info is received within the specified PacketReplyTimeout

Recently I installed aTalk (xmpp client - fork from jitsi-android) on Samsung S3 (GT-I9100) which is a slower device for testing.

After few attempts to relaunch the apps, I am still facing the same problem that vcard-temp avatar is not loaded properly; Smack reported packet received timeout error even after I have increased the PacketReplyTimeout to 30 seconds, and avatar is actually received ~5 seconds after get.

Based on the following captured Smack debug message, the vcard-temp iq was sent on:

02-15 13:44:48.810 D/SMACK: SENT (0):

and vard-temp avatar should have been received ~5 seconds based on the next received message i.e.

02-15 13:44:53.825 D/SMACK: RECV (0):

However smack still reports timeout after the specified 30 seconds PacketReplyTimeout which has been set.

I have included the whole debug log in case the problem is due to sequence order or race conditions.

Just realized that there are multiple in the end Tag i.e. can this be a cause?

Note: Yesterday, I just upgraded the home ejabberd xmpp server from version 16.08 to version 17.01+ (source build based on master source from repository). I have checked the ejabberd.log, but the data was truncated and unable to tell if this is from ejabberd server.

================ Actual log with trimmed for space ============

02-15 13:44:23.790 I/αTalk: [4] org.jivesoftware.smackx.avatar.vcardavatar.VCardAvatarManager.getAvatarImageByJ id() Fetching VCard avatar from cache for: (cmeng@atalk.org) => 2cbdb881330986f8c9e77493235725bbedb7d604

02-15 13:44:23.820 I/αTalk: [4] org.jivesoftware.smackx.avatar.vcardavatar.VCardAvatarManager.getAvatarImageByJ id() Fetching VCard avatar from cache for: (leopard@atalk.org) => ed341d7cb4d39f423989c0cf5fe8d9527be3ffde

02-15 13:44:47.520 D/SMACK: SENT (0): <stream:stream xmlns=‘jabber:client’ to=‘atalk.org’ xmlns:stream=‘http://etherx.jabber.org/streams’ version=‘1.0’ xml:lang=‘en’>

02-15 13:44:47.525 D/SMACK: RECV (0): <?xml version='1.0'?><stream:stream id=‘10788910183213240696’ version=‘1.0’ xml:lang=‘en’ xmlns:stream=‘http://etherx.jabber.org/streams’ from=‘atalk.org’ xmlns=‘jabber:client’>stream:featuresSCRAM-SHA-1PLAINX-OAUTH2</stream:features>

02-15 13:44:47.530 D/SMACK: SENT (0):

02-15 13:44:47.535 D/SMACK: RECV (0):

02-15 13:44:47.635 D/SMACK: SENT (0): <stream:stream xmlns=‘jabber:client’ to=‘atalk.org’ xmlns:stream=‘http://etherx.jabber.org/streams’ version=‘1.0’ xml:lang=‘en’>

02-15 13:44:47.640 D/SMACK: RECV (0): <?xml version='1.0'?><stream:stream id=‘15954350536456603937’ version=‘1.0’ xml:lang=‘en’ xmlns:stream=‘http://etherx.jabber.org/streams’ from=‘atalk.org’ xmlns=‘jabber:client’>

02-15 13:44:47.645 D/SMACK: RECV (0): stream:featuresSCRAM-SHA-1PLAINX-OAUTH2</stream:features>

02-15 13:44:47.650 I/αTalk: [3] impl.protocol.jabber.ProtocolProviderServiceJabberImpl.connected().1374 Smack: CP Connection Successful

02-15 13:44:47.760 D/SMACK: SENT (0): biwsbj1zd2FuLHI9MDE5MyJYelt0RyQiZ0h2YzM8K31ZY3RfR0U2KHV yUn4=

02-15 13:44:47.765 D/SMACK: RECV (0): cj0wMTkzIlh6W3RHJCJnSHZjMzwrfVljdF9HRT YodXJSfjVHa0pjbzJWM0pIc2FheG1KOU80ZXc9PSxzPTdjNktCSnNaTHdTYjNZSytqdVRXb2c9PSxpPT QwOTY=

02-15 13:44:48.320 D/SMACK: SENT (0): Yz1iaXdzLHI9MDE5MyJYelt0RyQiZ0h2YzM8K3 1ZY3RfR0U2KHVyUn41R2tKY28yVjNKSHNhYXhtSjlPNGV3PT0scD1peGtsVDFqREJNQmcyTHdmd2hDMU dJVXViSHc9

02-15 13:44:48.325 D/SMACK: RECV (0): dj12SUF5UHdqVkVFZ1AydmxEV0Mya0hTL3BCY0 E9

02-15 13:44:48.325 D/SMACK: SENT (0): <stream:stream xmlns=‘jabber:client’ to=‘atalk.org’ xmlns:stream=‘http://etherx.jabber.org/streams’ version=‘1.0’ id=‘15954350536456603937’ xml:lang=‘en’>

02-15 13:44:48.330 D/SMACK: RECV (0): <?xml version='1.0'?><stream:stream id=‘5785033886695730492’ version=‘1.0’ xml:lang=‘en’ xmlns:stream=‘http://etherx.jabber.org/streams’ from=‘atalk.org’ xmlns=‘jabber:client’>

02-15 13:44:48.330 D/SMACK: RECV (0): stream:features</stream:features>

02-15 13:44:48.335 D/SMACK: SENT (0): atalk

02-15 13:44:48.430 D/SMACK: RECV (0): swan@atalk.org/atalk

02-15 13:44:48.435 D/SMACK: User logged (0): swan@atalk.org:5222/atalk

02-15 13:44:48.450 D/SMACK: SENT (0):

02-15 13:44:48.455 I/αTalk: [3] impl.protocol.jabber.ProtocolProviderServiceJabberImpl.authenticated().1391 Smack: User Authenticated-isResumed: false

02-15 13:44:48.460 D/SMACK: RECV (0):

02-15 13:44:48.490 D/SMACK: SENT (0):

02-15 13:44:48.495 D/SMACK: RECV (0):

02-15 13:44:48.625 I/αTalk: [3] org.jivesoftware.smackx.avatar.vcardavatar.packet.VCardTempXUpdate.setAvatarHas h() Account avatar hash updated with (old => new):

null

02-15 13:44:48.630 I/αTalk: [3] org.jivesoftware.smackx.avatar.vcardavatar.VCardAvatarManager.downloadVCard() Downloaded vcard info for: swan@atalk.org; Hash =

02-15 13:44:48.690 I/αTalk: [4] org.jivesoftware.smackx.avatar.vcardavatar.VCardAvatarManager.getAvatarImageByJ id() Fetching VCard avatar from cache for: (xyz123@atalk.org) => 050be6d940f8c5515bafcc95f02f55a87615ffad

02-15 13:44:48.720 D/SMACK: SENT (0):

02-15 13:44:48.725 D/SMACK: RECV (0):

02-15 13:44:48.730 I/αTalk: [5] impl.protocol.jabber.OperationSetPersistentPresenceJabberImpl.publishPresenceSt atus().602 Smack: sending presence:available/

02-15 13:44:48.740 D/SMACK: SENT (0): 30

02-15 13:44:48.775 D/SMACK: RECV (0): ed341d7cb4d39f423989c0cf5fe8d9527be3ffde</ph oto>30

02-15 13:44:48.790 D/SMACK: RECV (0): 910ec77e99e8fbf80778932ef26902f5ebe650df</ph oto>30

02-15 13:44:48.805 I/αTalk: [7] org.jivesoftware.smackx.avatar.vcardavatar.VCardAvatarManager.parseContactPhoto Presence() Presence with new avatarHash received (old => new) from: abc123@atalk.org/jitsi-1ulb6en

null

910ec77e99e8fbf80778932ef26902f5ebe650df

02-15 13:44:48.810 D/SMACK: SENT (0):

02-15 13:44:48.810 D/SMACK: RECV (0): 30

02-15 13:44:48.810 D/SMACK: RECV (0):

02-15 13:44:48.830 D/SMACK: SENT (0):

02-15 13:44:48.930 D/SMACK: XMPPConnection authenticated (XMPPTCPConnection[swan@atalk.org/atalk] (0))

02-15 13:44:49.005 D/SMACK: RECV (0):

02-15 13:44:49.005 D/SMACK: RECV (0): image/jpegiVBORw0KGgoAAAANSUhEUg AAAGAAAABgCAIAAABt+uBvAAAjPklEQVR42t2dB1hTV//H35Lk7uTem0UgjDBkb1Cp1To7rFvr3qNVq+ LeVsVt3VIU3Av3FkXcWm2t1mpdbbXat76t2lrrAhJIzrn/c28CBmQEte9L/8/ze/KQe5PA+fj9rXN+yL +AYPufGfwL2OYDEAlhJLS1hkISsI2BwioAdgDbMSB8D2y/AfgMCFbJ/jc/5L/+R2ieArAKghhBoASBhl APYQ0IgwHwgVCLngqQR7cAQNf9IIwF1sYQDgC2kcA2G9i22xA++B0QbouIBQsQCv4+gv99QGYAMiGsJQ ikIGAQ+gDQCsCpUFgChc+hsADA6QBMttkaCwIDYSCE7QGoB2EcABEAVIPQWxAIQZChRwhVEJqgEAas9Q WhPYSDAJwF4AqbdR8ULgDhJgD3gZBTiM9a9QEVAPAtBB9KK3xDgAwA9SGcDIVUiU6hw

Nnz3orad4BiGUMWtKS7/0SgHKPJF5drUZXEJFn2Ql2QJeXMygq/VcA/XUf7lwDpg4vmPKJLXkgWPApUo 0djd1cAbQ/U0uria/PRUJokraBlILAPX7EBniQdkA0zjMq4suvvF4C0MN

02-15 13:44:49.020 D/SMACK: RECV (0): 94T9uMNij8rPseETkG9RtZMf//S726A+wdxOcMQoFGmvyADj/U7g9zRmNaCe2VQRIkZ/PJiayNM36ev GN6iiHfeKxfIXhm29Mf/xualzHk1BRjEKjVBIUqV443/MlAP2+3R9VQPavn0rF9O8oJDml+R+yX/t8kP kpyNximzHSmtwPTBkK508UtqWXRCMZ3L8ebK9TLiB2wxojoyUXLQpM/tTQrqMuPJrWanmWYZRaiuJ5il ATSoaiVCqCQ3fLTGTlAnJqOEJRJHJsgJxu+FOG5+…

tWkPkpPJkFPxsHkgdapwyA8yaUhQZdhOsWgGlDwfqocgDl5niGhhr6fOxeeLDFQsg+e2L87qJpy0Zjv/ 5agtIo1ISC1LEEGxyoLCjgKwUIeda9ndUKo3X9+9tMUDogQ/Ho1kZPezy6cbz7awBkNT+

Q5hQzEJ2KANsSTdPHo3yYL5fVB5nep7yeD87oCPBplIAjQlCdIpbKDYrDB8Uovo4KGJUQPfxpnkzjXuX ef602z1/nw5kar9cw4csieeW1CJSElBklZwiQbTpsdTkGGJsJDE0hBgQJO9pknXylrX1lLVCIDxlzSVr VkjE2Vp4FmLylLXwEE16Wh4gtOYoX4MIiGaQiEI9+KeZq6VbW+9sXupv5PQ4iekUtfxMf+xYXvyNW4QD 663pc8yRNUsA+iIm2DVAyKLwBVGKUSGKgcHkwAj0iA8MZUZHBEwLb7Qowm9OGDs5DhsVLB8QKO8XKDpF R6PsQ7Q2o4OCg4VXJay1p6y9Ud7VW97PS9beywVAx7dE+XrYG0gVRUcZdXlZGwpvbf2oaV0lqVLiHI1p moYHmw+V8vbceg1LALrYIPp0XFAJQNjYUJFICsIUIlqKqCD881BibQSxMwpfEakYGYReJksKx

02-15 13:44:49.025 D/SMACK: RECV (0): LjxfR/LcAvXQGgNb52SvtjLCJoYiRbFehgpqLS8KGlw1oSQCxCPmLHzbapOjnI+/uIw5NFY3g2SfsWn ggyuIkkXjFMZdHtfT36hZXd0zrAZ+Pyji2/fzNS1UXkJ3RvIMrUH9vnyHC0iIdgMQBQiM21quo/CFSAv CZ/tgEX9FfevmIA3Qt7eOYzlNoxufWwlNCYyRbmSL71/9wRu8pGfOyzh/5+fc7ufm5VeAvs1SG0Zys5V hSsJj7hzhNmDU3ygf4Kkb5yj/2lnX2krXydPiLXR0vTicW3lK3C40a0KDngqHzdqSd/O7Le4/u59ssVe 9P11SS0ewD6XZGCvTYyuBYf3NjsYnU5oWhpPnzWIu38DV0inp/QschaROXZ2ec/eGbJ3lPrKCgyv9tn8 ozmrl/qSIpSDEo2BFKnuvCs2hkV5yqauFdrU+tFsndpmyaf+DcwZ/u/Wy2mv+Bf/zoJRgJ1hmZS8hPIm QtPZx9h/swOG7wu30WD1+4Z/mpK2f+fPawAOT/8/861MvarL1pXJegZhO7Dls+ed3Rzd/cuIRiKtLX3/ cd/w8rZrw5npcDPwAAAABJRU5ErkJggg==</BINVAL

02-15 13:44:53.825 D/SMACK: RECV (0):

02-15 13:45:18.830 E/αTalk: [7] org.jivesoftware.smackx.avatar.vcardavatar.VCardAvatarManager.downloadVCard() Error while downloading VCard for: abc123@atalk.org. Exception: No response received within reply timeout. Timeout was 30000ms (~30s). Waited for response using: IQReplyFilter: iqAndIdFilter (AndFilter: (OrFilter: (IQTypeFilter: type=error, IQTypeFilter: type=result), StanzaIdFilter: id=Xqaky-57)), : fromFilter (OrFilter: (FromMatchesFilter (full): abc123@atalk.org)).

02-15 13:45:18.850 D/SMACK: SENT (0):

02-15 13:45:18.875 D/SMACK: RECV (0):

Can you debug why

Waited for response using: IQReplyFilter: iqAndIdFilter (AndFilter: (OrFilter: (IQTypeFilter: type=error, IQTypeFilter: type=result), StanzaIdFilter: id=Xqaky-57)), : fromFilter (OrFilter: (FromMatchesFilter (full): abc123@atalk.org)).

did not match the stanza with id Xqaky-57?

From the debug log, it appears that the received data should have match the filters pattern, instead of reported timeout.

During the debug session, this was what I have observed:

a. due to large avatar data, the complete avatar data was received in 3 segments

b. when the third segment was received, smack did not react to it. It appeared that smack seems to not aware that the complete data had arrived for processing.

c. smack waited and reported timeout at the end of the 30-second PacketReplyTimeout

d. One thing I observed is that the avatar end Tag was split with empty white spaces as shown below. I suspect this may had led to smack unable to detect it had actually received the complete package for processing.


</BINVAL


I have checked the ejabberd server mysql database, the stored avatar data is ok and does not contain these white spaces. I just upgraded the ejabberd server with source build from the latest master repository (v17.0x). Ejabberd log file contains only the truncated avatar data, so I can not tell if the extra white spaces are introduced by ejabberd. I hope smack team will able to ascertain the data is received and displayed as raw without any intermediate processing. Also if the above white spaces causes problem in the smack detection of the received data and matching of the filter.

I retested the same on my Note 3, it too contains spaces in the end Tag of third received segment. However smack seems to accept it and does not report timeout in this case i.e. vcard download is successfully.

Note: smack debug info on some of the received avatar, does not even contains the end Tag, look like it is being truncated for display.

------------- Avatar third segment data tested on Note 3 -------------

/u59ssVe9P11SS0ewD6XZGCvTYyuBYf3NjsYnU5oWhpPnzWIu38DV0inp/QschaROXZ2ec/eGbJ3lPrK Cgyv9tn8ozmrl/qSIpSDEo2BFKnuvCs2hkV5yqauFdrU+tFsndpmyaf+DcwZ/u/Wy2mv+Bf/zoJRgJ1h mZS8hPImQtPZx9h/swOG7wu30WD1+4Z/mpK2f+fPawAOT/8/861MvarL1pXJegZhO7Dls+ed3Rzd/cuI RiKtLX3/cd/w8rZrw5npcDPwAAAABJRU5ErkJggg==

02-18 10:57:34.393 I/αTalk: [8] org.jivesoftware.smackx.avatar.vcardavatar.VCardAvatarManager.downloadVCard() Downloaded vcard info for: abc123@atalk.org; Hash = 910ec77e99e8fbf80778932ef26902f5ebe650df


I run the test again on Samsung S3. Beside earlier reported problem. I found it has many other problems e.g. the client takes more than 16 seconds to response to sasl challenge, and get disconnected by the server on timeout before it has chance to responds to the xmpp-bind request on first attempt to login. Avatar request for other contacts success rate is also not consistent.

Look like the observed problem is nothing to do with smack. I believe S3 being a old device, its speed is just not fast enough for aTalk to handle all the received data for processing.

You may close the issue for now. Will come back again if I found otherwise.