aTalk release 4.1.0 implements XEP-0264: Jingle Content Thumbnails support for File Transfer protocol in both:
a. XEP-0234: Jingle File Transfer
b. XEP-0096: SI File Transfer
Upon received of a File Transfer Request with thumbnail element, a Bob data request is sent. However it is found that the requester needs to wait ~16s before the bob data is received, if the thumbnail size is set to 128 x 96. This long wait is not practical, as the recipient will likely to click the Accept button before even the thumbnail is received and displayed.
Following are the logcats captured while carried out test with swan sending a file transfer request to swordfish.
From above it is found that the requester swan sends the bob data immediately after received the bob data request from swordfish. However swordfish receives the requested bob data only after a wait
of ~16s. On further checking with ejabberd log data, it indicates that swan actually segmented the bob data in sending. This is the cause of the delay, even though ejabberd relays the bob data in a single stanza sending.
Please advice if there is a way to get bob data sending without data segmentation to avoid the long delay wait.
2024-05-13 07:58:38.270456+08:00 [notice] <0.4433.2> (tls|<0.4433.2>) Received XML on stream = <<"<iq to='swan@atalk.sytes.net/atalk-1jgccqn' id='6YRF5-37' type='get'><data xmlns='urn:xmpp:bob' cid='sha1+5222d9938627302cc16ac8a7b587be40880b1dc8@bob.xmpp.org'/></iq>">>
2024-05-13 07:58:38.281664+08:00 [notice] <0.4438.2> (tls|<0.4438.2>) Send XML on stream = <<"<iq xml:lang='en' to='swan@atalk.sytes.net/atalk-1jgccqn' from='swordfish@atalk.sytes.net/atalk-1tsh01p' type='get' id='6YRF5-37'><data xmlns='urn:xmpp:bob' cid='sha1+5222d9938627302cc16ac8a7b587be40880b1dc8@bob.xmpp.org'/></iq>">>
2024-05-13 07:58:38.306607+08:00 [notice] <0.4438.2> (tls|<0.4438.2>) Received XML on stream = <<"<iq to='swordfish@atalk.sytes.net/atalk-1tsh01p' id='6YRF5-37' type='result'><data xmlns='urn:xmpp:bob' cid='sha1+5222d9938627302cc16ac8a7b587be40880b1dc8@bob.xmpp.org' max_age='86400' type='image/jpeg'>/9j/4AAQSkZJRgABAQAAAQABAAD/4gHYSUNDX1BST0ZJTEUAAQEAAAHIAAAAAAQwAABtbnRyUkdCIFhZWiAH4AABAAEAAAAAAABhY3Nw
2024-05-13 07:58:45.351467+08:00 [notice] <0.4438.2> (tls|<0.4438.2>) Received XML on stream = <<"GPvj0lsMsSfxr8nfGZvCuq57CT2QhMHmOvcsN7HVc0rVNl2KlsHgCmIFIPo6EvFln3o8roKkRmqR1DcEKKx0SyTWjdG1McPGMhyjnnP69/qxbk0cW855mxM2eh2OHNWTgSbp5yDR1N4Fq7ppvF6qTmR0k2kQQDXKuHvH0muEl4ist8xba3IDKpIIEe5uw/I+Ij+R1Q2aye73XCll3R+wt+C8b2BFIHcxklpmSYInpWi
2024-05-13 07:58:53.544397+08:00 [notice] <0.4438.2> (tls|<0.4438.2>) Received XML on stream =
L2krFf8Au16NX0mhOodP0jtxWuNL4yzksbSndYasnrVKj1K9UMb5DurPULtIPuJIksehV03qZua+ldRV6hgeo2JyO4KoVVUA2pJCgAAlgADAHAl4uv8A5S4Ll3jH1ryUi8xfHnWN5iZoCKPLcuVsGNjsYyhUAOSzUl+9hjF3R6GJnFBctS6lG0Nv0UvzzsesaH+GUL2eTfMGRyr9GIwQb8FX5NcjsyaX+Pv369K5fkvpF9qn4y3+GPkHDLCrMHSWN0ci/JN7zn4qqfFGr6drkVfS+/f+ntU/f36/HQlx7C8PteJ/LoNJzrHePx7xiFS6+0dtGAu2KdJ6HoMwMz+/sMMgpyBKih+5ZZoI1K6OrXEWAlQOOCXsjQnWDJay1vbWOBucda5Cy1fWz1HJ4qpUxWS09bHDUquEvjSuri0bKC9yBuL6nRs6Nrjbe6u3rXaRRRKZZtdo3RmSr520yF9Z32nqOGvMXkkXJYjMBcg1LLWIq2tK5SwNra+hbNWu61zf1ra3Sjbud7MYH//Z</data></iq>
2024-05-13 07:58:53.572463+08:00 [notice] <0.4433.2> (tls|<0.4433.2>) Send XML on stream = <<"<iq xml:lang='en-US' to='swordfish@atalk.sytes.net/atalk-1tsh01p' from='swan@atalk.sytes.net/atalk-1jgccqn' type='result' id='6YRF5-37'><data xmlns='urn:xmpp:bob' cid='sha1+5222d9938627302cc16ac8a7b587be40880b1dc8@bob.xmpp.org' max_age='86400' type='image/jpeg'>/9j/4AAQSkZJRgABAQAAAQABAAD/4gHYSUNDX1BST0ZJTEUAAQEAAAHIAAAAAAQwAABtbnRyUkdCIFhZWiAH4AABAAEAAAAAAABhY3NwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAQAA9tYAAQAAAADTLQAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAlkZXNjAAAA8AAAACRyWFlaAAABFAAAABRnWFlaAAABKAAAABRiWFlaAAABPAAAABR3dHB0AAABUAAAABRyVFJDAAABZAAAAChnVFJDAAABZAAAAChiVFJDAAABZAAAAChjcHJ0AAABjAAAADxtbHVjAAAAAAAAAAEAAAAMZW5VUwAAAAgAAAAcAHMAUgBHAEJYWVogAAAAAAAAb6IAADj1AAADkFhZWiAAAAAAAABimQAAt4UAABjaWFlaIAAAAAAAACSgAAAPhAAAts9YWVogAAAAAAAA9tYAAQAAAADTLXBhcmEAAAAAAAQAAAACZmYAAPKnAAANWQAAE9AAAApbAAAAAAAAAABtbHVjAAAAAAAAAAEAAAAMZW5VUwAAACAAAAAcAEcAbwBvAGcAbABlACAASQBuAGMALgAgADIAMAAxADb/2w
sMMgpyBKih+5ZZoI1K6OrXEWAlQOOCXsjQnWDJay1vbWOBucda5Cy1fWz1HJ4qpUxWS09bHDUquEvjSuri0bKC9yBuL6nRs6Nrjbe6u3rXaRRRKZZtdo3RmSr520yF9Z32nqOGvMXkkXJYjMBcg1LLWIq2tK5SwNra+hbNWu61zf1ra3Sjbud7MYH//Z</data></iq>">>
Actually I have already included ejabberd log in my first comment. From the aTalk logcat, I can only see the initial Bob data sent by swan. To understand which is causing the delay, I proceeded to check the ejabberd log. Found that ejabberd was receiving the the Bob data sent from swan in 3 segments at ~7s interval. I have clean up, reformat with comment and attached the ejabberd log below.
I am not sure if there is an underlying handshakes between smack and ejabberd to segment the Bob data transfer; as I did not see ejabberd log on this process.
To confirm the observation, I change the thumbnail to png format, the bob size increases to >50K, and found it was again segmented into 7 instances, leading to ~48s delay in Bob data transfer.
// ======= ejabberd log with comments ========
// ==== ejabberd receives the stanza from swordfish for Bob request
2024-05-13 07:58:38.270456+08:00 [notice] <0.4433.2> (tls|<0.4433.2>)
Received XML on stream =
<iq to='swan@atalk.sytes.net/atalk-1jgccqn' id='6YRF5-37' type='get'>
<data xmlns='urn:xmpp:bob' cid='sha1+5222d9938627302cc16ac8a7b587be40880b1dc8@bob.xmpp.org'/>
</iq>
// === ejabbred relays the Bob request to swan ====.
2024-05-13 07:58:38.281664+08:00 [notice] <0.4438.2> (tls|<0.4438.2>)
Send XML on stream = <iq xml:lang='en' to='swan@atalk.sytes.net/atalk-1jgccqn' from='swordfish@atalk.sytes.net/atalk-1tsh01p' type='get' id='6YRF5-37'>
<data xmlns='urn:xmpp:bob' cid='sha1+5222d9938627302cc16ac8a7b587be40880b1dc8@bob.xmpp.org'/>
</iq>
// ==== Found smack segemented and sent the bob data to ejabberd on 3 instances, at ~7 seconds interval ====.
2024-05-13 07:58:38.306607+08:00 [notice] <0.4438.2> (tls|<0.4438.2>) Received XML on stream =
<iq to='swordfish@atalk.sytes.net/atalk-1tsh01p' id='6YRF5-37' type='result'>
<data xmlns='urn:xmpp:bob' cid='sha1+5222d9938627302cc16ac8a7b587be40880b1dc8@bob.xmpp.org' max_age='86400' type='image/jpeg'>
/9j/4AAQSkZJRgABAQAAAQABAAD/4gHYSUNDX1BST0ZJTEUAAQEAAAHIAAAAAAQwAABtbnRyUkdCIFhZWiAH4AABAAEAAAAAAABhY3Nw
2024-05-13 07:58:45.351467+08:00 [notice] <0.4438.2> (tls|<0.4438.2>) Received XML on stream =
...
GPvj0lsMsSfxr8nfGZvCuq57CT2QhMHmOvcsN7HVc0rVNl2KlsHgCmIFIPo6EvFln3o8roKkRmqR1DcEKKx0SyTWjdG1McPGMhyjnnP69/qxbk0cW855mxM2eh2OHNWTgSbp5yDR1N4Fq7ppvF6qTmR0k2kQQDXKuHvH0muEl4ist8xba3IDKpIIEe5uw/I+Ij+R1Q2aye73XCll3R+wt+C8b2BFIHcxklpmSYInpWi
2024-05-13 07:58:53.544397+08:00 [notice] <0.4438.2> (tls|<0.4438.2>) Received XML on stream =
...
C9yBuL6nRs6Nrjbe6u3rXaRRRKZZtdo3RmSr520yF9Z32nqOGvMXkkXJYjMBcg1LLWIq2tK5SwNra+hbNWu61zf1ra3Sjbud7MYH//Z
</data>
</iq>
// ==== ejabberd immediately relay all Bob data to swordfish on complete received of the Bob data from swan ===
2024-05-13 07:58:53.572463+08:00 [notice] <0.4433.2> (tls|<0.4433.2>) Send XML on stream =
<iq xml:lang='en-US' to='swordfish@atalk.sytes.net/atalk-1tsh01p' from='swan@atalk.sytes.net/atalk-1jgccqn' type='result' id='6YRF5-37'>
<data xmlns='urn:xmpp:bob' cid='sha1+5222d9938627302cc16ac8a7b587be40880b1dc8@bob.xmpp.org' max_age='86400' type='image/jpeg'>
/9j/4AAQSkZJRgABAQAAAQABAAD/4gHYSUNDX1BST0ZJTEUAAQEAAAHIAAAAAAQwAABtbnRyUkdCIFhZ
....
OGvMXkkXJYjMBcg1LLWIq2tK5SwNra+hbNWu61zf1ra3Sjbud7MYH//Z
</data>
</iq>
I found that the sent stanza segmentation also happens for other xmpp protocols with large data transfer i.e.
a. Avatar data
b. vCard BINVAL
I did an estimation of each segment data size received by ejabberd (based on its log), found that each is ~8K; and each segment send interval is 7~9s, except in the case for Avatar data second data segment which occur in ms.
Transmission Control Protocol (TCP) is helpful to send a file or message over a connected network. Each file gets divided into packets at the sender network. The packets get merged on arrival at the receiving network. The maximum size of a TCP packet is 64K (65535 bytes). Generally, the packet size gets restricted by the Maximum Transmission Unit (MTU) of network resources. MTU is the maximum size of the data transfer limit set by hardware in a network. The packet size should never exceed MTU . In this tutorial, we’ll try to explain the concept behind each of these terms and explore various aspects of it.
// ======= Avatar segmented byte size = 8K ======
2024-06-03 06:37:20.490915+08:00 [notice] (tls|<0.11992.1>) Received XML on stream = <<"<iq id='DFLCV-36' type='set'><pubsub xmlns='http://jabber.org/protocol/pubsub'><publish node='urn:xmpp:avatar:data'><item id='e068b4aafe48bf1943f2a0707b18146b8dc5bc63'><data xmlns='urn:xmpp:avatar:data'>iVBORw0KGgoAAAANSUhEUgAAAGwAAABsCAIAAAAABMCaAAAAAXNSR0IArs4c6QAAAANzQklUCAgI\n2+FP4AAA
2024-06-03 06:37:20.496760+08:00 [notice] (tls|<0.11992.1>) Received XML on stream = <<"4N3Q+OYwRZACIIeO8H\nAMVQoL2N3hNkheDYBBZrrPchNsSugjhfBFItgf7k5384tf6YG2692qQzjcZsEOS+CIo9BMJKxEiI\n4Vn5XDiK
2024-06-03 06:37:27.689317+08:00 [notice] (tls|<0.11992.1>) Received XML on stream = <<"McePOW2+Bimw6a+Fn42o2o8W7t13+7Q9OW2QKqL3RorTG3lqtyfLHGXl9H0l+bzK/\nwky7Hzb5ZVbdLzsJrQE3wXQcyNwXEyaliRSpyd51PmjDIsTCBKUUSKmJsyiKEBNUWZZxYilLxcOL\nUkoVzrug0kR3R/6elVE81QgVvvSNy4Lu5M50V3cBXkdxHIKUeadF1vc+9e/vTgSoYBOoSNX5SGeT\nPrT95PTYyn4wbt9DOb7gPnYiA2ujStcuOw5X1K6IIwOQiFF
...
RgAAAAASUVORK5CYII=</data></item></publish></pubsub></iq><r xmlns='urn:xmpp:sm:3'/>">>
// ======= vCard BINVAL segmented byte size = 8K ======
2024-06-03 06:37:31.980172+08:00 [notice] (tls|<0.11992.1>) Received XML on stream = <<"<iq id='DFLCV-35' type='set'><vCard xmlns='vcard-temp'><BDAY>Dec 18, 1992</BDAY><PHOTO><BINVAL>iVBORw0KGgoAAAANSUhEUgAAAGwAAABsCAIAAAAABMCaAAAAAXNSR0IArs4c6QAAAANzQklUCAgI2+FP4AAAIABJREFUeJzkvXm0ZVV1L/ybq9ndae499966VVRDAdIjGOyb2CRqlNjEJsRANMHmJRoTu4yo70kiMcZgfCbRaOKz1xg/
2024-06-03 06:37:40.172978+08:00 [notice] (tls|<0.11992.1>) Received XML on stream = <<"RWldSsM61aS+aIqBj0QvA+a/Q+u2T0Kf2RiVWmKycWIdRoRgoJwCEoZiBrXBpp90m0fKkrWSkYFwKSRjrFm900qUNfYcVJgquCZFMBKj8qqmaTwVdbK7unhixf8pM/N/33W+5sbj2CKvJjuaJA0lBAI
2024-06-03 06:37:48.364488+08:00 [notice] (tls|<0.11992.1>) Received XML on stream = <<"lf+dTpzlIqm47Sx7Rc3TWUmFue6uS9X3/bXf/zyUx/dtFAeDYVIAaGC1mNnSdbU2X7Ju1+DCU37ZCNkzUUkjM1ohjHwDGNgI8sInkWzIQUCfP
....
AAASUVORK5CYII=</BINVAL><TYPE>image/jpeg</TYPE></PHOTO></vCard></iq><a xmlns='urn:xmpp:sm:3' h='47'/>">>
At this point a tcp dump would be helpful. Especially the timing of the arrival of the ACKs of those 8 KiB TCP packets would be interesting. But maybe it reveals also something else.
No, Smack has no such limit. At least directly. I could speculate that 8 KiB is the limit of a involved BufferedWriter, as it is exactly 2x 4 KiB pages. But even if it is the case, then there is probably something additionally going on, like a delayed ACK.
Test Setup:
a. Swan (file sender) on android AVD API-34 running on Ubuntu 22.05
b. Swordfish (file recipient) on android Note10+ device
c. ejabberd server on host with Ubuntu 20.04
d. WireShark app is running on Swan Ubuntu Host
The Thumbnail send file size : image/png 128x96;
Below are all the log info for your analysis:
For this test, the file send is formatted as png with 128x96. The file size captured on ejabberd is
a. File send from swan: Size = 6937
b. File Relay to swordfish: Size = 23120
Because the generated thumbnail size < 8K, swan actual upload to ejabberd in one single transaction ~5s after received Bob request from swordfish. It seems that ejabberd performs some image conversion before relay the thumbnail to swordfish.
Note: the thumbnail file is pre-generated before file send request is initiated.
Will do another test with image/jpeg format to see the difference if any.
// ===== ejabberd log =====
2024-06-05 07:14:43.239412+08:00 [notice] (tls|<0.6290.0>) Received XML on stream = "<iq to='swan@atalk.sytes.net/atalk-23mgn7a' id='6XTWH-56' type='get'><data xmlns='urn:xmpp:bob' cid='sha1+389ab700eb3c8a9b8c6b99bb600fbe7691a03832@bob.xmpp.org'/></iq>"
2024-06-05 07:14:43.252622+08:00 [notice] (tls|<0.6283.0>) Send XML on stream = "<iq xml:lang='en' to='swan@atalk.sytes.net/atalk-23mgn7a' from='swordfish@atalk.sytes.net/atalk-kok1g0' type='get' id='6XTWH-56'><data xmlns='urn:xmpp:bob' cid='sha1+389ab700eb3c8a9b8c6b99bb600fbe7691a03832@bob.xmpp.org'/></iq>"
2024-06-05 07:14:48.491390+08:00 [notice] (tls|<0.6283.0>) Received XML on stream = "Av8/8/wBn/wCfrk/1H4bzYLY8wEsVNWa4eNSxDwmCsqKrnH/jVj+HEnSmiQRJba1NEbHkdrQ93KlkTDhOz1i2jaCa1F/
2024-06-05 07:14:48.518206+08:00 [debug] Flushing packets of swan@atalk.sytes.net from CSI queue of swordfish@atalk.sytes.net/atalk-kok1g0
2024-06-05 07:14:48.518891+08:00 [notice] (tls|<0.6290.0>) Send XML on stream = "<iq xml:lang='en-US' to='swordfish@atalk.sytes.net/atalk-kok1g0' from='swan@atalk.sytes.net/atalk-23mgn7a' type='result' id='6XTWH-55'><data xmlns='urn:xmpp:bob' cid='sha1+389ab700eb3c8a9b8c6b99bb600fbe7691a03832@bob.xmpp.org' max_age='86400' type='image/png'>/9j/4AAQSkZJRgA...NWaiK6Cn//2Q==</data></iq>"
Pcap captured IP Address:port info:
a. 202.166.54.243:5222 (ejabberd server)
b. 192.168.194 (swan)
c. 192.168.1.167 (swordfish)
File transfer info: Setup as before. swan => swordfish
a. Thumbnail file size = 39352 bytes (image/jpeg)
b. No image file conversation found at ejabberd
d. ejabberd receive data in 4 segmentation
e. Delay in thumbnail received by swordfish after Bob request: ~23s
Attached is the pcap captured on ejabberd server (at different file transfer instance), but with similar setup except: Swordfish (sender) => swan (recipient).
192.168.1.8 => ejabberd local IP
202.166.54.243 => ejabberd public IP.