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