IBB FileTransfer incorrectly reports isDone() just after first data chunk

[Vitaly Takmazov]

Prerequisites:

1. Other client sends file to babbler instance and they are negotiate IBB

2. Other client sends file in multiple chunks

What I do: I have add simple FileTransferStatusListener and check for isDone() in it

What I get and what I expect: Got true just after first data chunk, while I should receive all data chunks before it.

[Christian Schudt]

I couldn't reproduce it, neither on the sender, nor on the receiver side. There's a FileTransferIT#testInBandFileTransfer test, which tests IBB. isDone() is conform to the status: IN_PROGRESS: false IN_PROGRESS: false COMPLETED: true and is false while transferring the file.

Do you have a simple test case?

[Vitaly Takmazov]

testInBandFileTransfer sends 4-byte data (in one chunk I guess), is it possible to easy add a test which split data in multiple chunks?

[Christian Schudt]

I just did that: 2ad49de, but it still works fine. 9x isDone() = false, the last one is true.

[Vitaly Takmazov]

That client uses old ibb spec with data chunks in message and opens ibb stream without stanza=message attribute. With client following latest spec (stanza=iq) all works fine

[Christian Schudt]

I've written a test, which tests IBB with message stanzas: 6e6a1e7 Unfortunately I still cannot reproduce your issue.

The output is as follows:

IN  (4ae50q2car): <message><data xmlns="http://jabber.org/protocol/ibb" ...
IN_PROGRESS, false
IN  (4ae50q2car): <message><data xmlns="http://jabber.org/protocol/ibb" ...
IN_PROGRESS, false
IN  (4ae50q2car): <message><data xmlns="http://jabber.org/protocol/ibb" ...
IN_PROGRESS, false
IN  (4ae50q2car): <iq ... type="set"><close xmlns="http://jabber.org/protocol/ibb" sid="c189af05-cf03-4d2e-9977-c039c2b35c78"></close></iq>
COMPLETED, true

[Vitaly Takmazov]

does this test add stanza=message to open ? Can you please try without it?

[Vitaly Takmazov]

This is the ibb log from "ibbclient" to "babbler" as I see in logs (except jids) which unexpectly "completed". The only difference with normal log I see is absence of stanza=message. And maybe message is bigger than block-size? (but I doubt)

<iq xmlns="jabber:server" type="set" to="babbler" from="ibbclient" id="241:188115" lang="en-US"><si xmlns="http://jabber.org/protocol/si" id="89200221" profile="http://jabber.org/protocol/si/profile/file-transfer" mime-type="application/octet-stream"><file xmlns="http://jabber.org/protocol/si/profile/file-transfer" name="A8ur-0uCMAA0dA-.jpg" size="22580"><desc xmlns="http://jabber.org/protocol/si/profile/file-transfer">#2835575 test ibb</desc></file><feature xmlns="http://jabber.org/protocol/feature-neg"><x xmlns="jabber:x:data" type="form"><field xmlns="jabber:x:data" type="list-single" var="stream-method"><option xmlns="jabber:x:data"><value xmlns="jabber:x:data">http://jabber.org/protocol/ibb</value></option></field></x></feature></si></iq>

<iq from="babbler" id="241:188115" to="ibbclient" type="result"><si xmlns="http://jabber.org/protocol/si"><feature xmlns="http://jabber.org/protocol/feature-neg"><x xmlns="jabber:x:data" type="submit"><field type="list-single" var="stream-method"><value>http://jabber.org/protocol/ibb</value></field></x></feature></si></iq>

<iq xmlns="jabber:server" type="set" to="babbler" from="ibbclient" id="242:650157" lang="en-US"><open xmlns="http://jabber.org/protocol/ibb" block-size="1024" sid="89200221"></open></iq>
<iq from="babbler" id="242:650157" to="ibbclient" type="result"></iq>
XMPPConnection - transfer started
<message xmlns="jabber:server" lang="en-US" to="babbler" from="ibbclient"><data xmlns="http://jabber.org/protocol/ibb" seq="0" sid="89200221">/9j/4AAQSkZJRgABAQEASABIAAD/2wBDAAgGBgcGBQgHBwcJCQgKDBQNDAsLDBkSEw8UHRofHh0aHBwgJC4nICIsIxwcKDcpLDAxNDQ0Hyc5PTgyPC4zNDL/2wBDAQkJCQwLDBgNDRgyIRwhMjIyMjIyMjIyMjIyMjIyMjIyMjIyMjIyMjIyMjIyMjIyMjIyMjIyMjIyMjIyMjIyMjL/wAARCADuAlgDASIAAhEBAxEB/8QAHAAAAAcBAQAAAAAAAAAAAAAAAAECAwQFBgcI/8QAWRAAAQMCBAMDBgkGCgcFCAMAAQACAwQRBRIhMQZBURMiYQcUMnGBkRUjQlWTobHB0RczUuHi8AgkRVNUYnKSlLIWNDU2dIKkJTii0vEYKDdDRFZjZHOjs//EABoBAAIDAQEAAAAAAAAAAAAAAAABAgMEBQb/xAArEQACAgEDBAIBBQADAQAAAAAAAQIRAxIhMQQUQVETIhUFIzNSYSQyoUL/2gAMAwEAAhEDEQA/AO8OcXHwQCFkoDZMQAELJSCAE2QslBCyBCUEqyJACLIWSrIEIARZGAjsjQMIBGgggAIiEaSSgAiUguQc62qynGfGVLwth+dxElXJpDDfU+J6BAGlmqIoWZpHta3qSofwvQudlbVRE+DwvPVfxfimLVD5qupe4E6MboweoJr4UAa5oeQ75Tgba9FHUS0neMZ4qwrBKYz1lS0Dk0G7j6gsHU+WekErhT4bI5g2L5LE+xcwxJktXeR9RMXW2LvRCoZYpoXXzX8Dok2wUTutF5YMNmcBV0M0Lf02PDvqWzwniPCccbegrYpX7mO9nj/lOq8tQzl/dzOa7a26sKWpnp5GyNc5jmm4fGbEH2Ja2h6E+D1QSkFcs4P8o84kjosbf2sbrNZVc29M3X7fWuote2Rgexwc1wuCDcEKakmQlGhLkw9SHJl4UiA2iKVZJISGENkmi29pSgk0fP8AtFAeUWI2Uik/PBR26tUikHxwSJFiEpJCUmAaJBGhDCQCNBAARWRoIAJBHZCyACQSrIWQAmyCVZCyAEoWSrIWSATZHZHZBMArIWRo0AJshdGhZIAkXNKshZMBKCVZFZIAkEdkEAEjQ9qHJABFBE9wYC48lUVfElDSOLXSBzhyalY0m+C4uiJWdHGWG3vJIWjra9vWrCkxihrbCKqic4nQB2+qSkhuMlyiyvoiOxSWuvzRnUKREymMXNfJZVbgQQ5WuLf7Qeq0jvDRTM0uQVYIpRayre9Y3VxVi1KFVSO2ACkiDRLwnE5cOq2Oa49k42kYdiPxQUMDXkghpDU2tjp3NKCTulBVmoNEj5IBAg0EEEAgIijRIAIhFZKRFAwrI0ECgAiggURQAQ==</data></message>
<message xmlns="jabber:server" lang="en-US" to="babbler" from="ibbclient"><data xmlns="http://jabber.org/protocol/ibb" seq="1" sid="89200221">EpBKMlNOKAK3HcapsCwqevq32jjGjb6uPIBeaMex2qx/FpcQqn9+R3caDoxvIDwAWs8qvFRxbFzh1NJ/FKVxYLHR7/lO+qw9q5o+XdVt2yxR2sl+choNtmjT1qM2sczUOO9yVGfLcEA7psG9hzCEDLmKtcXDNq7pyCfnjZOxoYM0h36BVdOCSLakrWYRhrn5XOFh1Krnk0luPG5Mzk2ETZf633J+kimb3JhcbB3MevqF0KPBY5mHu+1QavAZIHFzI7t8AqfmZoWBGZETqeWzm906EdPH7F1jgPiLPTtw+ofcXyxuPI8vf9vrWCqKPNCCWmw2c3kpmF3jaS0kX/R+0e1XY5eSnJj8HbCU05QMGxB2JYXDO8jtQMktv0hz9uh9qnclouzF5oSiKMpJ2QAOSTRjV39opQ2RUnpO/tH7UA+Swb6KkUv54KO06KRS/ngkSLEbI0QRhMYaCCCQACNEheyYB8kEV0eZABorIXQzIANBFmQzIANCyLMhmSAUAgk5kMx6oAUgk5j1RZigBXNBJuhcoAWgk5ihmPVACkEnMeqGYoAOyKyFz1QuUACyFkVykyStjYXOIACAFWTNRVR08eZ7mj1myosU4ww/D2kmTMRfRouVzDEuKcZ4wxX4PwiFzm3uQNGtF93O5BVzyRii3HicmafjTjyOipn0tM60zr3dfYLj9TxNildUlsbnMG1xpoup0XkyhdCZMRqTPUu1OQWaE3UeTGONrn07WnqCs7yyfg0xxwjwznhqsQpqbtGPz35k2cChHxRXwsuW2IN7iwAUriOlrcNrBG5j2tb3e8PcSqacQPm1ABcNcmyIttDbdm74V8qrnSClr25mg9119V1jC+IaHFIWOgfa5y94jfpdeU6p0eHzNe1oDXHQ35LS8PcTVGFztqKZ/aU8lhJCToVZHI1yVTxp8HdsW1rZOarspvt+tQsGxymxuPtI59CAMrt2+BV6MPvqH+o2WqLtWjn5ItNpkasb/FByVM8G5Wolw/tIAwuIUM4I0/8AzCpoqaKNjdboK9GCNaNXlBMWlmxRhJCUFUaxSKyHJBAg0ESCADRIIIACCCCBgRFGiQARSSj5JJKAEOKznGmNHAeFK2tY602Xs4v7btB+PsWhcuReWfFABh2GNdzdPIL9NBdKTpDirZxqsmL53OLiSNLnn1Ve917+Kkym7ifWo7GOkfYa2VSLWNO3RxgueAN+SXLHkbmOgOytMBw81lRct7oRJ0rCMblRbYHhYyiR7depWxo4Wss1oUBkIhYA0aBTqWeUyCKmi7WXmTo0LHJ6mdCCUUaTD4+QGqu4qFkoALRr1WYZR8SNs8S0kLOjRmKeosdxamq2Q1pikjvq5rbJpJcicw==</data></message>
<message xmlns="jabber:server" lang="en-US" to="babbler" from="ibbclient"><data xmlns="http://jabber.org/protocol/ibb" seq="2" sid="89200221">vgssX4YDI3VVKwHTvx8nDw8VkDQ+ayZoyTTSu7hPyHc2n1/iF0ijxEVocxpuAsBjkFWcYqKWlkDIXkOfcXsfxVmpJ2iNNqmX3CFd2VfJRuJDZgS0E7PGtvddbQjRclbVzYfWw1WcdpA8dpYcxs4eB+9dVhnZUU8c8Z7kjQ5vqIutWOVmDNGnYqyIhAuRZiplIBsk0vpu/tH7UobJNL6bv7RQD5LFuyfpfzwUceipFJ+fCRIsgjG6o+IuJ6PhqOjdVQVk76ybsIIqSAyvc+xdbKD0CRgPF2HY9Wz0MUdZSV9OwSSUldTOglDCbBwDtxfS4TGaFFdDXofciukApFzQsggAII79bor+v3JgBBC/rR39aACQQJ9apKviF1Hiow04XiMsz3RiF8cJdHI1x7zs/otyc8xB2te6LAu0NUATbn7kL9frQAEEDtfZCyAAghZBAAQshZHZABIIgjCABZK0RIIAPRDTxRWQskAiaRsUTnusGgXJXP8AinihwZIyBwETRdxBsStPj1eynpZBnAIaba815544xsR1dRBE/MWtyOc06ElVZJPhFuOKu2Rq/iLEcXq3RQuLu0flblGp5ABdq4OwSHh7BIobA1MgD538y7p6hsuX+SvBu2LsSqI7ujsI7j5R5+5dup6fPG3bqsbbcmbKSRIZML2T7ZtLGyaZTgDknOwuNVYrIOipxnAaDG4Sya7XgHK4clxriXhuowCocKqIS05PclYy/wD6LucsBZ3mqlxiGGrpHwzsDg4bFRk6dkoqzzhi7oqpgb6FuRH3pjCYHujkjae8w5rHcrVcYcKvpGuqYW9wG5HRZLCJJBUhzS22UixWiDUsexXNaHuaOlxOswPFIaqJ7mxu3ts4HcLsnDHEMeM0WaN4zs0IuuJtnFY3s3jVulr7hWXDeLT4Fi7ZLO7M+m0dEoS0yohmgpxPQEmYQiziooe8yDvHkhS1sdbh0VRC7NG9twU203katq4OY073J1QXCLRyCTUaNagmFmhBSrpASgqjSKBRpKNAgIIIJgGggiKQw0EV9UaAAiQRFABHZNkpZKbcUAIcbrzt5T6/zzjWrs7MyFoiFuVt16HJsbnYLyxxHUOqOIKyV5u50rifa8qvJxRPHyUEly4+ASrtpod7k6I3seZCxjHOe4hrWtFyf3shiVFNQTUxmLXdrGJA1lyWX5O8fBRssadWQ3l88gc7QDRrei33C9CIKASEd5+qxMeZ8rWhu/ILoWCOPmbW/olV5ntRbgX2LDsb+A6pbq6HBIWZGF9RKfi4wL38Sjc42trvyVjRw0M9u3ha6QaB5PeA6A9FmTNmmxPYYriuFh7qrs5XvAMQizkM5ki4GnQeKz0tJjGHuJfHMw==</data></message>
XMPPConnection - transfer completed

[Vitaly Takmazov]

Also I'm using 0.7.4, but I didn't see anything changed in filetransfer in next commits

[Christian Schudt]

Yes, the test adds message because it is not the default. I've ommitted it for test purposes, but the result is the same. The message in your data elements is 1024, so this should be fine.

Maybe there's an exception somewhere? Is fileTransfer.getException()non-null?

What's causing head aches is that your "ibbclient" (or rather your server) is sending in the "jabber:server" namespace although it should be "jabber:client". Not sure if this is relevant to your issue, but maybe.

[Vitaly Takmazov]

getException() is:

java.net.SocketTimeoutException: null
        at rocks.xmpp.extensions.bytestreams.ibb.IbbInputStream.fillBuffer(IbbInputStream.java:131)
        at rocks.xmpp.extensions.bytestreams.ibb.IbbInputStream.read(IbbInputStream.java:73)
        at java.io.InputStream.read(InputStream.java:101)
        at rocks.xmpp.extensions.filetransfer.FileTransfer.lambda$transfer$63(FileTransfer.java:178)

jabber:server

My babbler instance is external component and I have complex routing :)

[Christian Schudt]

Seems like the data queue is empty for too long, when reading from it.

Is it possible that the messages arrive too slow?

The default read time out for IBB streams is xmppSession.getConfiguration().getDefaultResponseTimeout()

as a side note, jabber:server is used for server-to-server connections only. For external components it should actually be jabber:component:accept

[Vitaly Takmazov]

So my problem was in my FileTransferStatusListener which should not rely on isDone() "shortcut" as it includes failed status, and it should check the received status before trying to use received file and should handle failed status, thanks for the help!

[Christian Schudt]

Well, maybe. isDoneis designed like Future#isDone, it returns true, even when failed with exception.