Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Nexus 5, Android 4.4.4: "fatal error got type 0 (CONTAINER_UNDEFINED) in response" #75

Closed
andreasf opened this issue Nov 13, 2014 · 45 comments
Closed

Nexus 5, Android 4.4.4: "fatal error got type 0 (CONTAINER_UNDEFINED) in response" #75

andreasf opened this issue Nov 13, 2014 · 45 comments

Comments

@andreasf
Copy link
Contributor

Affected version: 689b5b4
OS: Linux 3.17.2-300.fc21.x86_64
Related to issue: #23

After successfully mounting my phone, I try to rsync a folder to my computer. It works for a few files, until the connection is closed with the following errors:

2014/11/13 10:33:55 FUSE mounted
2014/11/13 10:34:16 fatal error got type 0 (CONTAINER_UNDEFINED) in response, want CONTAINER_RESPONSE.; closing connection.
2014/11/13 10:34:16 AndroidGetPartialObject64 failed: got type 0 (CONTAINER_UNDEFINED) in response, want CONTAINER_RESPONSE.
2014/11/13 10:34:16 AndroidGetPartialObject64 failed: mtp: cannot run operation ANDROID_GET_PARTIAL_OBJECT64, device is not open
2014/11/13 10:34:16 AndroidGetPartialObject64 failed: mtp: cannot run operation ANDROID_GET_PARTIAL_OBJECT64, device is not open
2014/11/13 10:34:16 AndroidGetPartialObject64 failed: mtp: cannot run operation ANDROID_GET_PARTIAL_OBJECT64, device is not open
2014/11/13 10:34:16 AndroidGetPartialObject64 failed: mtp: cannot run operation ANDROID_GET_PARTIAL_OBJECT64, device is not open
...

Apparently, this happens as a result to an ANDROID_GET_PARTIAL_OBJECT64 request:

2014/11/13 10:40:06 MTP request ANDROID_GET_PARTIAL_OBJECT64 [543 0 0 62964]
2014/11/13 10:40:06 MTP data 0xf600 bytes
2014/11/13 10:40:06 MTP bulk read 0x4000 bytes.
2014/11/13 10:40:06 MTP bulk read 0x4000 bytes.
2014/11/13 10:40:06 MTP bulk read 0x4000 bytes.
2014/11/13 10:40:06 MTP bulk read 0x3400 bytes.
2014/11/13 10:40:11 MTP response 0x0 []
2014/11/13 10:40:11 fatal error got type 0 (CONTAINER_UNDEFINED) in response, want CONTAINER_RESPONSE.; closing connection.

Debug logs, created with --debug=fs,mtp,usb:
@juhanima
Copy link

juhanima commented Feb 9, 2015

Detected the same problem when copying all the media contents out of my Nexus 7. It seems that the culprit is the following code at the end of bulkRead at go-mtpfs/mtp.go:

if lastRead%packetSize == 0 {
    // Null read.
    d.h.BulkTransfer(d.fetchEp, buf[:0], d.Timeout)
}

...as it seems when running with -debug=mtp, the previous bulk read just before the error always returns a number of bytes divisible by 512(0x200), which is the case also in andreasf's log.

I'm new to go and have no idea what the "Null read" is supposed to do. But it seems to me that the extra BulkTransfer call returns the CONTAINER_UNDEFINED status and causes the closing of the connection. Removing both the check and the extra read seems to fix the problem.

@hanwen
Copy link
Owner

hanwen commented Feb 9, 2015

it's been a while, but from what I can remember, you have to read until you reach the end of the stream. If the stream is exactly the size of the buffer then you need another read to make sure you really reached the end.

What size is the file that generated the error?

@juhanima
Copy link

Sorry for the delay. Could be that this happened with files with a size of a multiple of 4096 bytes. Don't have the logs any more, sorry. The code seems to attempt what you say, but I think the problem is there is one read too many.

The loop in bulkRead exits if there is an error in write or if lastRead < len(toread), where len(toreadI I believe is 4096. If the size of the file is a multiple of that, the, last read calls return values ...,4096, 4096, 4096 and finally 0, which makes the loop exit. Since 0 % 512 == 0, yet another read is made and that's one too many at least for some devices.

I suppose there might be differences between devices. As said, I tested with a Nexus 7 and Android lollipop. How about changing the test to "if lastRead > 0 AND lastRead%packetSize == 0"?

@andreasf
Copy link
Contributor Author

I just rsynced files from my phone, and the problem happened with a 2364404 bytes large file (not divisible by 4096). The following is repeatable for me:

$ dd if=/dev/zero of=testfile bs=1 count=2364404
$ cp testfile ~/nexus/Internal\ storage/
# restart/remount go-mtpfs...
$ rsync --progress nexus/Internal\ storage/testfile ~/testfile2
testfile
      2,364,404 100%  218.40kB/s    0:00:10 (xfr#1, to-chk=0/1)
rsync: read errors mapping "/home/user/nexus/Internal storage/testfile": Input/output error (5)
WARNING: testfile failed verification -- update discarded (will try again).
testfile
      2,364,404 100%  225.49MB/s    0:00:00 (xfr#2, to-chk=0/1)
rsync: read errors mapping "/home/user/nexus/Internal storage/testfile": Input/output error (5)
ERROR: testfile failed verification -- update discarded.
rsync error: some files/attrs were not transferred (see previous errors) (code 23) at main.c(1165) [sender=3.1.1]

Output from go-mtpfs:

2015/03/19 18:26:22 FUSE mounted
2015/03/19 18:26:49 fatal error got type 0 (CONTAINER_UNDEFINED) in response, want CONTAINER_RESPONSE.; closing connection.
2015/03/19 18:26:55 AndroidGetPartialObject64 failed: got type 0 (CONTAINER_UNDEFINED) in response, want CONTAINER_RESPONSE.
2015/03/19 18:26:55 AndroidGetPartialObject64 failed: mtp: cannot run operation ANDROID_GET_PARTIAL_OBJECT64, device is not open

@juhanima
Copy link

Do you mean the error happened with my suggested change? If so, I guess it's not a good fix then.

For what it's worth, those go-mtpfs errors look very familiar, especially the "got type 0 (CONTAINER_UNDEFINED) in response, want CONTAINER RESPONSE". That's what I got.

I'll see if I can reproduce the problem once more. Thanks for the response, anyway!

@andreasf
Copy link
Contributor Author

No, the error happens with the current HEAD.

I did some debugging with Wireshark, and saw that the response to the null read is an EOVERFLOW error. After finding this in the libusb documentation, i changed bulkRead to use the whole buffer at the end:

    if lastRead%packetSize == 0 {
        // Null read.
        d.h.BulkTransfer(d.fetchEp, buf[:], d.Timeout)
    }

Wireshark now showed the 16 bytes response from the device:

10 00 00 00 03 00 01 20 35 00 00 00 f4 13 00 00
|           |     |     |           |
|           |     |     |           ` 0x000013f4: payload, should be specific to ANDROID_GET_PARTIAL_OBJECT64
|           |     |     ` 0x00000035: transaction id
|           |     ` 0x2001: pima 15740 response code: OK
|            ` 0x0003: container type: response
` 0x00000010: container length: 16 bytes

So actually, this is the CONTAINER_RESPONSE packet that fetchPacket is supposed to receive after the bulk transfer. Because the packet is discarded, fetchPacket afterwards reads 0 bytes and its empty buffer is misinterpreted as container type 0x0000 (CONTAINER_UNDEFINED), which causes the error.

So the null read is actually harmful, and commenting it out solves the issue for me. Is it really required for some devices?

@andreasf
Copy link
Contributor Author

From the PTP specification (PDF page 29):

The Data phase ends when the number of bytes transferred equals the number of bytes specified in the first four bytes of the Data Block that coincide with a short or a NULL packet. A short packet or a NULL packet indicates the end of the end of a Data phase. If the number of bytes specified in the first four bytes of the Data Block are an integral multiple of the wMaxPacketSize field of the Endpoint Descriptor the Data phase will end in a NULL packet.

So the null packet should be there if h.Length % packetSize == 0. If all previously received packets also are divisible by packetSize (they should be -- first read is packetSize large, bulk reads are 0x4000), then checking the size of lastRead is equivalent. Also, wMaxPacketSize is 512 bytes for the Bulk IN MTP endpoint of the Nexus 5. Is this a protocol implementation error in Android?

Concerning the size of my example file: if you add 12 bytes of headers, it is divisible by 512.

@hanwen
Copy link
Owner

hanwen commented Mar 20, 2015

all of these reports are for the android extensions, right? Can you confirm that things work for the standard MTP protocol (-android=false)?

It's entirely possible that there are bugs in go-mtpfs, but for the android extensions, it's probably the only piece of software to exercise them, so it may also be a problem on the android side.

@andreasf
Copy link
Contributor Author

I think the behavior of go-mtpfs is correct. Currently i'm trying to understand the Android MTP gadget source, which also implements the null packet case:

https://android.googlesource.com/kernel/msm/+/android-5.0.2_r0.2/drivers/usb/gadget/f_mtp.c#673

@andreasf
Copy link
Contributor Author

(Edited)
The Android 5.0.2 MTP driver I linked to appears to have an integer overflow bug in line 710, where xfer is 0 and hdr_size should be 12. -12 casted to an unsigned size_t should lead to an error in vfs_read, so that send_file_work would not send the null packet. xfer is 12, so there is no overflow.

But actually I don't have Android 5.0.2 on my phone, I have 5.0.1, and none of the branches/tags I checked for 5.0 / 5.0.1 / 4.4 / "Lollipop Release" have this bug. So again I'm clueless about what's happening ;-)

@andreasf
Copy link
Contributor Author

I did a few more packet dumps with Wireshark and this time disabled the Android extensions. The behavior is the same: neither go-mtpfs nor Wireshark receive a null packet. Here are the pcap files, if anybody wants to take a look:

I also tried a Sandisk Sansa Clip+ I had lying around. After adding "PIMA" as an allowed substring in Device.Open(), I was able to mount the device and run the same tests. Interestingly, the Sansa behaves just as the Nexus, no null packets:

While the Sansa claims that the bulk transfer container size is file size + 12 bytes, the header it sends is actually 45 bytes large. I therefore tried to copy a 33 bytes smaller file, so that the real container size is divisible by 512. Again, no null packet:

@juhanima
Copy link

juhanima commented Apr 2, 2015

Hanwen wrote:

all of these reports are for the android extensions, right?
Can you confirm that things work for the standard MTP protocol (-android=false)?

I'm sorry but I'm not quite sure what the standard MTP protocol is and what are the Android extensions. My Android tablet was the first time I encountered this protocol. Wikipedia says that "MTP is part of the 'Windows Media' framework", so I guess standard MTP is something Windows specific, right?

I'm afraid I cannot verify whether the problem applies to the standard Windows Media framework, as I have no idea of how to do that. I just wanted to copy media files from my Android tablet to my Linux computer and vice versa. I think andreasf has amply proved that an extraneous read after EOF is harmful with Android implementations, which indeed might be a bug in Android itself.

It's entirely possible that there are bugs in go-mtpfs, but for the android extensions,
it's probably the only piece of software to exercise them, so it may also be a problem
on the android side.

Looks to me like a necessary work-around in one context and a harmful feature in another. Would not be the first time. I take it from the gist of your reply that the main purpose of this software is to communicate with some Windows systems and Android is more like a sidekick. If so, I think it's quite all right for you to take no action, as we probably wouldn't want you to break something more important because of this. I'm happy with my patch which suits my purposes well and I hope andreasf is as well.

Anyway, many thanks for a great piece of software. I have to say I was quite impressed of the quality of it when browsing through the source code. It's clearly superiour to any other Android <-> Linux file transfer solutions I have seen so far.

@hanwen
Copy link
Owner

hanwen commented Apr 2, 2015

Quite the contrary. I don't use windows and only use go-mtpfs with Android.
It's been a while that I've looked at mtp, and don't have much time lately
and for this reason I'm asking for some more data. I'll try to set aside a
few hours this weekend to look more closely.

Op do 2 apr. 2015 22:48 schreef Juhani Mäkelä notifications@github.com:

Hanwen wrote:

all of these reports are for the android extensions, right?
Can you confirm that things work for the standard MTP protocol
(-android=false)?

I'm sorry but I'm not quite sure what the standard MTP protocol is and
what are the Android extensions. My Android tablet was the first time I
encountered this protocol. Wikipedia says that "MTP is part of the 'Windows
Media' framework", so I guess standard MTP is something Windows specific,
right?

I'm afraid I cannot verify whether the problem applies to the standard
Windows Media framework, as I have no idea of how to do that. I just wanted
to copy media files from my Android tablet to my Linux computer and vice
versa. I think andreasf has amply proved that an extraneous read after EOF
is harmful with Android implementations, which indeed might be a bug in
Android itself.

It's entirely possible that there are bugs in go-mtpfs, but for the
android extensions,
it's probably the only piece of software to exercise them, so it may also
be a problem
on the android side.

Looks to me like a necessary work-around in another context and a harmful
feature in another. Would not be the first time. I take it from the gist of
your reply that the main purpose of this software is to communicate with
some Windows systems and Android is more like a sidekick. If so, I think
it's quite all right for you to take no action, as we probably wouldn't
want you to break something more important because of this. I'm happy with
my patch which suits my purposes well and I hope andreasf is as well.

Anyway, many thanks for a great piece of software. I have to say I was
quite impressed of the quality of it when browsing through the source code.
It's clearly superiour to any other Android <-> Linux file transfer
solutions I have seen so far.

—
Reply to this email directly or view it on GitHub
#75 (comment).

@andreasf
Copy link
Contributor Author

andreasf commented Apr 2, 2015

I'm quite confused about the missing null packet. I don't see it in
Wireshark, but according to the protocol specification and the Android
MTP gadget source it should be there. For a real fix, more investigation is
needed. For a quick fix, if you hit the issue, try commenting out the null
read.
On Apr 2, 2015 11:28 PM, "Han-Wen Nienhuys" notifications@github.com
wrote:

Quite the contrary. I don't use windows and only use go-mtpfs with Android.
It's been a while that I've looked at mtp, and don't have much time lately
and for this reason I'm asking for some more data. I'll try to set aside a
few hours this weekend to look more closely.

Op do 2 apr. 2015 22:48 schreef Juhani Mäkelä notifications@github.com:

Hanwen wrote:

all of these reports are for the android extensions, right?
Can you confirm that things work for the standard MTP protocol
(-android=false)?

I'm sorry but I'm not quite sure what the standard MTP protocol is and
what are the Android extensions. My Android tablet was the first time I
encountered this protocol. Wikipedia says that "MTP is part of the
'Windows
Media' framework", so I guess standard MTP is something Windows specific,
right?

I'm afraid I cannot verify whether the problem applies to the standard
Windows Media framework, as I have no idea of how to do that. I just
wanted
to copy media files from my Android tablet to my Linux computer and vice
versa. I think andreasf has amply proved that an extraneous read after
EOF
is harmful with Android implementations, which indeed might be a bug in
Android itself.

It's entirely possible that there are bugs in go-mtpfs, but for the
android extensions,
it's probably the only piece of software to exercise them, so it may also
be a problem
on the android side.

Looks to me like a necessary work-around in another context and a harmful
feature in another. Would not be the first time. I take it from the gist
of
your reply that the main purpose of this software is to communicate with
some Windows systems and Android is more like a sidekick. If so, I think
it's quite all right for you to take no action, as we probably wouldn't
want you to break something more important because of this. I'm happy
with
my patch which suits my purposes well and I hope andreasf is as well.

Anyway, many thanks for a great piece of software. I have to say I was
quite impressed of the quality of it when browsing through the source
code.
It's clearly superiour to any other Android <-> Linux file transfer
solutions I have seen so far.

Reply to this email directly or view it on GitHub
#75 (comment).

Reply to this email directly or view it on GitHub
#75 (comment).

@juhanima
Copy link

juhanima commented Apr 2, 2015

Hi, guys!

It's been a while that I've looked at mtp, and don't have much time lately
and for this reason I'm asking for some more data.

Thanks for the quick response, hanwen! It's very good to know that Android is the main use case.

What comes to lack of time, please let us know how we could help! It's Easter here in Europe, and I have a lot of time to use and a Nexus 9 with which to test.

What you andreasf are saying might be a good starting point. I have to confess you have gone so deep I haven't quite been able to follow. Anyway, now reading again what you wrote and quoted:

The Data phase ends when the number of bytes transferred equals
the number of bytes specified in the first four bytes of the Data Block that
coincide with a short or a NULL packet.

What does this mean? Does it mean that data ends when the number of bytes returned is less than the number requested? What is a NULL packet? If one has already gotten a zero bytes returned, why ask for another one?

A short packet or a NULL packet indicates the end of the end of a Data phase.

I guess a NULL packet is a zero length packet that comes if the data available was divisible by the packet size requested? So that the one read before last got the requested amount and the next one gets zero?

If the number of bytes specified in the first four bytes of the Data Block are
an integral multiple of the wMaxPacketSize field of the Endpoint Descriptor
the Data phase will end in a NULL packet.

There you are! Isn't the right reading algorithm then: keep requesting n bytes until less than n bytes is returned. When returned < n, it means there is no more data, regardless if returned is zero or greater than zero. A null packet only comes if the number of available data bytes is divisible by the requested size.

Mind you, I have shot myself in the foot with this one before. In Linux/Unix/Posix there is an error condition EINTR which means that the system call was interrupted, and there is actually more data to come even if the current read was cut short. So the right algorithm is

if returned == requested or erc == EINTR then keep reading...

I wonder... anyway, please let me know how I can help.

@hanwen
Copy link
Owner

hanwen commented Apr 2, 2015

Andreas, what does your "about phone" say for the version number? The puzzling thing is: I have a stock nexus 5, and it works flawlessly here,

[hanwen@pomba go-mtpfs]$ rsync --progress /tmp/x/Interne\ opslag/testfile /tmp/tf2
testfile
2,364,404 100% 16.72MB/s 0:00:00 (xfr#1, to-chk=0/1)
[hanwen@pomba go-mtpfs]$ ls -l /tmp/tf2
-rw-r--r--. 1 hanwen hanwen 2364404 Apr 3 00:27 /tmp/tf2

I was also surprised, since I recall writing test cases for these cases:

add a panic in the null read

cd mtp/ && go test
=>
panic

disable null read:

cd mtp/ && go test
=>
works

enable null read:

cd mtp/ && go test
=>
works

in other words, over here, it seems to not make a difference if I do the null read or not. Does the test pass on your side?

I have:

Nexus 5,
Android 5.0.1
Build LRX22C

@hanwen
Copy link
Owner

hanwen commented Apr 2, 2015

I could also copy the 2364404 byte file on my nexus 7, Android 5.1 build LMY47D

@juhanima
Copy link

juhanima commented Apr 2, 2015

2364404/512
4617.9765
???

@andreasf
Copy link
Contributor Author

andreasf commented Apr 2, 2015

@juhanima If you add the 12 bytes header, it divides to 4618

@juhanima
Copy link

juhanima commented Apr 2, 2015

I see, OK. Still, wouldn't you need a bit more to prove there is no error than one isolated succesful case? After all, finding the error is usually the hardest part.

@andreasf
Copy link
Contributor Author

andreasf commented Apr 2, 2015

This is the result of go test (I added some printfs for debugging...):

$ go test
2015/04/03 01:06:59 Found a device candidate
2015/04/03 01:06:59 now selecting devices
2015/04/03 01:06:59 device added
2015/04/03 01:06:59 at offset: 1
2015/04/03 01:06:59 ID retrieved
2015/04/03 01:06:59 at offset: 2
2015/04/03 01:06:59 ID retrieved
2015/04/03 01:06:59 at offset: 3
2015/04/03 01:06:59 ID retrieved
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 319 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 12 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 12 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 20 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 12 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 24 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 12 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 12 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 12 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 16 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 12 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 54 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 12 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 17 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 16 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 12 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 16 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 12 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 67 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 12 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 12 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 12 bytes received in fetchPacket
2015/04/03 01:06:59 Found a device candidate
2015/04/03 01:06:59 now selecting devices
2015/04/03 01:06:59 device added
2015/04/03 01:06:59 at offset: 1
2015/04/03 01:06:59 ID retrieved
2015/04/03 01:06:59 at offset: 2
2015/04/03 01:06:59 ID retrieved
2015/04/03 01:06:59 at offset: 3
2015/04/03 01:06:59 ID retrieved
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 12 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 23 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 12 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 20 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 12 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 12 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 67 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 12 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 12 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 12 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 38 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 12 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 26 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 12 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 24 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 12 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 24 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 12 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 30 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 12 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 23 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 12 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 23 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 12 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 26 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 12 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 23 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 12 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 23 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 12 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 23 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 12 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 12 bytes received in fetchPacket
2015/04/03 01:06:59 Found a device candidate
2015/04/03 01:06:59 now selecting devices
2015/04/03 01:06:59 device added
2015/04/03 01:06:59 at offset: 1
2015/04/03 01:06:59 ID retrieved
2015/04/03 01:06:59 at offset: 2
2015/04/03 01:06:59 ID retrieved
2015/04/03 01:06:59 at offset: 3
2015/04/03 01:06:59 ID retrieved
2015/04/03 01:06:59 at offset: 1
2015/04/03 01:06:59 ID retrieved
2015/04/03 01:06:59 at offset: 2
2015/04/03 01:06:59 ID retrieved
2015/04/03 01:06:59 at offset: 3
2015/04/03 01:06:59 ID retrieved
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 319 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 12 bytes received in fetchPacket
2015/04/03 01:06:59 Found a device candidate
2015/04/03 01:06:59 now selecting devices
2015/04/03 01:06:59 device added
2015/04/03 01:06:59 at offset: 1
2015/04/03 01:06:59 ID retrieved
2015/04/03 01:06:59 at offset: 2
2015/04/03 01:06:59 ID retrieved
2015/04/03 01:06:59 at offset: 3
2015/04/03 01:06:59 ID retrieved
2015/04/03 01:06:59 at offset: 1
2015/04/03 01:06:59 ID retrieved
2015/04/03 01:06:59 at offset: 2
2015/04/03 01:06:59 ID retrieved
2015/04/03 01:06:59 at offset: 3
2015/04/03 01:06:59 ID retrieved
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 319 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 12 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 12 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 20 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 12 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 74 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 12 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 16 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 24 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 12 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 40 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 12 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 170 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 12 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 20 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 12 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:06:59 512 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:07:01 0 bytes received in fetchPacket
2015/04/03 01:07:01 fatal error got type 0 (CONTAINER_UNDEFINED) in response, want CONTAINER_RESPONSE.; closing connection.
2015/04/03 01:07:01 fetchPacket
2015/04/03 01:07:03 0 bytes received in fetchPacket
--- FAIL: TestDeviceStorage (4.55s)
    device_test.go:301: device: LGE Nexus 5 072094d20b359dd6
    device_test.go:308: device info stdv: 64, ext: 6, mtp: v64, mtp ext: "microsoft.com: 1.0; android.com: 1.0;" fmod: 0 ops: GetDeviceInfo, OpenSession, CloseSession, GetStorageIDs, GetStorageInfo, GetNumObjects, GetObjectHandles, GetObjectInfo, GetObject, GetThumb, DeleteObject, SendObjectInfo, SendObject, GetDevicePropDesc, GetDevicePropValue, SetDevicePropValue, ResetDevicePropValue, GetPartialObject, MTP_GetObjectPropsSupported, MTP_GetObjectPropDesc, MTP_GetObjectPropValue, MTP_SetObjectPropValue, MTP_GetObjPropList, MTP_GetObjectReferences, MTP_SetObjectReferences, ANDROID_GET_PARTIAL_OBJECT64, ANDROID_SEND_PARTIAL_OBJECT, ANDROID_TRUNCATE_OBJECT, ANDROID_BEGIN_EDIT_OBJECT, ANDROID_END_EDIT_OBJECT evs: ObjectAdded, ObjectRemoved, StoreAdded, StoreRemoved, DevicePropChanged dprops: MTP_SynchronizationPartner, MTP_DeviceFriendlyName, ImageSize, BatteryLevel fmts:  capfmts: Undefined, Association, Text, HTML, WAV, MP3, MPEG, EXIF_JPEG, TIFF_EP, BMP, GIF, JFIF, PNG, TIFF, MTP_WMA, MTP_OGG, MTP_AAC, MTP_MP4, MTP_MP2, MTP_3GP, MTP_AbstractAudioVideoPlaylist, MTP_WPLPlaylist, MTP_M3UPlaylist, MTP_PLSPlaylist, MTP_XMLDocument, MTP_FLAC manu: "LGE" model: "Nexus 5" devv: "1.0" serno: "072094d20b359dd6"
    device_test.go:321: mtp.Uint32Array{Values:[]uint32{0x10001}}
    device_test.go:334: mtp.StorageInfo{StorageType:0x3, FilesystemType:0x2, AccessCapability:0x0, MaxCapability:0x3235af000, FreeSpaceInBytes:0xdcade000, FreeSpaceInImages:0x40000000, StorageDescription:"Internal storage", VolumeLabel:""}
    device_test.go:341: num objects 0x20e2
    device_test.go:367: Sent objectinfo handle: 0x26b9
    device_test.go:401: info mtp.ObjectInfo{StorageID:0x10001, ObjectFormat:0x3000, ProtectionStatus:0x0, CompressedSize:0x3f4, ThumbFormat:0x0, ThumbCompressedSize:0x0, ThumbPixWidth:0x0, ThumbPixHeight:0x0, ImagePixWidth:0x0, ImagePixHeight:0x0, ImageBitDepth:0x0, ParentObject:0x0, AssociationType:0x0, AssociationDesc:0x0, SequenceNumber:0x0, Filename:"go-mtp-testfcf46d0", CaptureDate:time.Time{sec:63563620018, nsec:0, loc:(*time.Location)(0x867560)}, ModificationDate:time.Time{sec:63563620018, nsec:0, loc:(*time.Location)(0x867560)}, Keywords:""}
    device_test.go:409: info mtp.Uint64Value{Value:0x3f4}
    device_test.go:419: GetObject failed: got type 0 (CONTAINER_UNDEFINED) in response, want CONTAINER_RESPONSE.
FAIL
exit status 1
FAIL    github.com/hanwen/go-mtpfs/mtp  4.821s

Nexus 5, Android 5.1, Build LMY47I (but it was the same with 5.0.1)

@juhanima
Copy link

juhanima commented Apr 2, 2015

2015/04/03 01:06:59 512 bytes received in fetchPacket
2015/04/03 01:06:59 fetchPacket
2015/04/03 01:07:01 0 bytes received in fetchPacket
2015/04/03 01:07:01 fatal error got type 0 (CONTAINER_UNDEFINED) in response, want >CONTAINER_RESPONSE.; closing connection.

Yep, that's the problem. Got one packet of zero length. Since 0 % (packet-length-whatever) == 0, try yet another time, and get an CONTAINER_UNDEFINED. Bloody Android is too strict!

@hanwen
Copy link
Owner

hanwen commented Apr 2, 2015

I think 512 bytes is the normal packet size, to the point that it's hardcoded in the source code.

@juhanima
Copy link

juhanima commented Apr 2, 2015

Yes, 512 sounds very normal indeed.

@hanwen
Copy link
Owner

hanwen commented Apr 2, 2015

andreas, what's the kernel version on your phone? it's also in the About Phone entry.

@hanwen
Copy link
Owner

hanwen commented Apr 2, 2015

Note that the android version (5.1, 5.0, LMY47I etc.) is separate from the kernel.

@juhanima
Copy link

juhanima commented Apr 2, 2015

Hate to quote myself, but

if lastRead%packetSize == 0 {
    // Null read.
    d.h.BulkTransfer(d.fetchEp, buf[:0], d.Timeout)
}

@hanwen
Copy link
Owner

hanwen commented Apr 2, 2015

my kernel is 3.4.0-g88fbc66 (N5)

@juhanima
Copy link

juhanima commented Apr 2, 2015

Still suggesting

if 0 < lastRead && lastRead%packetSize == 0 {
    // Null read.
    d.h.BulkTransfer(d.fetchEp, buf[:0], d.Timeout)
}

@andreasf
Copy link
Contributor Author

andreasf commented Apr 2, 2015

@hanwen, does your Linux host use xhci or ehci for the USB connection to the phone (see dmesg output)?

I just stumbled upon this: http://www.spinics.net/lists/linux-usb/msg121502.html, and then tested go-mtpfs on an older Laptop with no USB3. The tests worked, and I can also see the null packet in Wireshark: http://zentrale1.com/~an/nexus5-ehci.pcapng

@hanwen
Copy link
Owner

hanwen commented Apr 2, 2015

that could be the problem. I have a lenovo T420, which only has USB2.

$ dmesg|grep ehci
=>
..
[ 6679.900836] usb 1-1.1: new high-speed USB device number 21 using ehci-pci
[ 6687.066597] usb 1-1.1: new high-speed USB device number 22 using ehci-pci

(and lots more).

@likewhoa likewhoa mentioned this issue Apr 15, 2015
Closed
@hanwen
Copy link
Owner

hanwen commented Apr 21, 2015

I have added a -skip-null-read flag in the xhci-workaround branch. Can you verify if it works for you?

@likewhoa
Copy link

@hanwen with this new command line flag I am able to successfully rsync/cp any data without causing any issues.

Nexus 6 with relating issue #90

EDIT: I take back what i said, it seems after a second rsync run just for kicks I was able to hit the issue again.

2015/04/21 14:01:54 AndroidGetPartialObject64 failed: mtp: cannot run operation ANDROID_GET_PARTIAL_OBJECT64, device is not open

rsync: read errors mapping ...: Input/output error (5)

[ 7626.163934] cfg80211:   (57240000 KHz - 63720000 KHz @ 2160000 KHz), (N/A, 4000 mBm)
[ 7717.241563] usb 2-2: reset high-speed USB device number 7 using xhci_hcd
[ 7717.241595] xhci_hcd 0000:00:14.0: Setup ERROR: setup context command for slot 6.
[ 7717.394612] usb 2-2: reset high-speed USB device number 7 using xhci_hcd
[ 7717.394650] xhci_hcd 0000:00:14.0: Setup ERROR: setup context command for slot 6.
[ 7717.547711] usb 2-2: reset high-speed USB device number 7 using xhci_hcd
[ 7717.559519] xhci_hcd 0000:00:14.0: xHCI xhci_drop_endpoint called with disabled ep ffff880096976680
[ 7717.559525] xhci_hcd 0000:00:14.0: xHCI xhci_drop_endpoint called with disabled ep ffff880096976640
[ 7717.559527] xhci_hcd 0000:00:14.0: xHCI xhci_drop_endpoint called with disabled ep ffff8800969766c0

@hanwen
Copy link
Owner

hanwen commented Apr 22, 2015

@likewhoa - is it reproducible? Is it related to file size of what you're trying to transfer?

@hanwen
Copy link
Owner

hanwen commented Apr 22, 2015

also, this bug is for ¨fatal error got type 0 (CONTAINER_UNDEFINED) in response" for XHCI (usb3) machines for files that are a multiple of the blocksize (when adding 12 bytes of header data). Can you confirm whether the issue you see is somehitng new or not?

@andreasf
Copy link
Contributor Author

@hanwen your workaround works for me. I'd like to suggest a more liberal way of handling the null packets, though:

andreasf@99976c9

By just checking whether a null packet is received or not, users don't need to add additional parameters. I tried it on both my old and new Thinkpad, and interestingly the received size is always 16 bytes, even with USB 2.0:

2015/04/22 17:14:15 Expected null packet, read 16 bytes

So maybe this is more complicated than necessary, but I'd rather be safe.

There's probably a better way, but this is how you can test the branch:

$ go get github.com/andreasf/go-mtpfs
$ cd $GOPATH/src/github.com/andreasf/go-mtpfs
$ git checkout liberal_null_read
$ mv $GOPATH/src/github.com/hanwen/go-mtpfs $GOPATH/src
$ mv $GOPATH/src/github.com/andreasf/go-mtpfs $GOPATH/src/github.com/hanwen
$ cd $GOPATH/src/github.com/hanwen/go-mtpfs
$ go install

@likewhoa
Copy link

@hanwen I can reproduce this and I have tested by running the following commands.

cd destination
rsync -acv /source/ . # Transferring over 400 files in 2 different directories while doing a checksum for ~4k files in ~40 directories.
dd if=/dev/uradom of=/source/5G count=5k bs=1M
mv -v /source/5G .

I noticed that when I mount the device I always get ```[10126.276741] usb 2-7: usbfs: process 18784 (go-mtpfs) did not claim interface 0 before use


At this point I cannot say that the problem still exist until it is triggered again but so far I have not been able to reproduce it until I just ran the same rsync command

winters.gif
3,471,297 100% 6.63MB/s 0:00:00 (xfr#59, ir-chk=1018/3092)
rsync: opendir "/tmp/nexus6/Internal storage/r" failed: Input/output error (5)


in dmesg I have

2015/04/22 11:16:23 AndroidGetPartialObject64 failed: mtp: cannot run operation ANDROID_GET_PARTIAL_OBJECT64, device is not open


This is happening randomly and I can't seem to find a sure way to reproduce it.

@andreasf
Copy link
Contributor Author

@likewhoa do you have any other MTP software installed, for instance gvfs-mtp, the nautilus backend? I'm asking because gvfs-mtp tends to take over the connection.

@likewhoa
Copy link

@andreasf The only gvfs stuff currently running is /usr/libexec/gvfsd & /usr/libexec/gvfs-udisks2-volume-monitor

@andreasf
Copy link
Contributor Author

@likewhoa I'd try to uninstall gvfs-mtp and test again. The package is called gvfs-mtp for Fedora and gvfs-backends for Debian.

@likewhoa
Copy link

@andreasf I don't have that package installed.

@andreasf
Copy link
Contributor Author

@likewhoa You only have the same issue if you can find a file that reliably triggers the bug. The file size + 12 needs to be divisible by 512. The file you mentioned doesn't divide by 2.

In your case, the device reset seems to come first. go-mtpfs probably shows CONTAINER_UNDEFINED because it receives no data after the reset. Have you tried whether it works on another host machine, or with an up-to-date kernel?

@likewhoa
Copy link

@andreasf The kernel is 3.14.17 so it's not that old of a kernel but I plan on updating to 3.17.x this weekend. I can't find a relaible way to reproduce the issue and until I can then it just seems like perhaps something else triggered it.

@hanwen
Copy link
Owner

hanwen commented Apr 23, 2015

@andreasf - yes that looks better. Can you open a pull request?

@andreasf andreasf mentioned this issue Apr 24, 2015
Closed
@andreasf
Copy link
Contributor Author

Thanks! PR opened.

@hanwen hanwen closed this as completed in d108c3d Apr 24, 2015
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@hanwen @andreasf @likewhoa @juhanima