android-file-transfer-linux
android-file-transfer-linux copied to clipboard
whoozle
fuse mtp file transfer errors
i have a little bash script to backup my handy contents. i have the same problem with jmtpfs which is not maintained anymore. i don't know where is the problem maybe the mtp lib from cyanogenmod is buggy.
phone sony z1 compact - cm 12.1 8.5.2016. i i find the time i will try a build of cm-13.0.
backup script https://gist.github.com/Micha-Btz/38a1b719b8701130458cd5084753ed8a this produces this error https://gist.github.com/Micha-Btz/3b929b19f111269540033984946cbb11 fitting logcat https://gist.github.com/Micha-Btz/d025fb150e28b2de3cd224291ffe9c42
hopefully you can find a solution thank Micha
can you run aft-mtp-mount with -d option? Input/Ouput error means exception happened, it would be very handy to know what exactly.
Do you use the latest version from git?
I used cyanogen for years (I use my old GS3 for testing, it runs CM android M), haven't seen errors like this.
I removed some old crap in 5c4eb5ab4ff220162cc2726c0da687a86a210e64 please try with the latest master
i did a clean build https://gist.github.com/Micha-Btz/756095fad734f439ef46ab698cb4277b and testet also some other usb ports.
rsync
sysiphus/sysiphus_packet.list 135,366 100% 14.65kB/s 0:00:09 (xfr#14, to-chk=0/15) rsync: read "/mnt/z1c/SD-Karte/sysiphus/.home-16-05-16.tar.bz2.gpg.GoGZwe": Input/output error (5) rsync: copy "/mnt/z1c/SD-Karte/sysiphus/.home-16-05-16.tar.bz2.gpg.GoGZwe" -> "sysiphus/home-16-05-16.tar.bz2.gpg": Input/output error (5) rsync: read "/mnt/z1c/SD-Karte/sysiphus/.home-16-05-17.tar.bz2.gpg.1CMgEo": Input/output error (5) rsync: copy "/mnt/z1c/SD-Karte/sysiphus/.home-16-05-17.tar.bz2.gpg.1CMgEo" -> "sysiphus/home-16-05-17.tar.bz2.gpg": Input/output error (5)
sent 1,033,145,077 bytes received 778 bytes 1,220,491.26 bytes/sec total size is 1,032,891,828 speedup is 1.00 rsync error: some files/attrs were not transferred (see previous errors) (code 23) at main.c(1183) [sender=3.1.1]
and here are the output from the debug run
unique: 285672, opcode: RENAME (12), nodeid: 1009845, insize: 106, pid: 14041 Rename 1009845 .owncloud-db-04092015.sql.9ZSsWX -> 1009845 owncloud-db-04092015.sql unique: 285672, error: -18 (Invalid cross-device link), outsize: 16 unique: 285673, opcode: OPEN (14), nodeid: 1012556, insize: 48, pid: 14041
unique: 285636, opcode: WRITE (16), nodeid: 1012555, insize: 8272, pid: 14041 Write 1012555 8192 266428416 unique: 285636, success, outsize: 24 unique: 285637, opcode: WRITE (16), nodeid: 1012555, insize: 8272, pid: 14041 Write 1012555 8192 266436608 unique: 285637, success, outsize: 24 unique: 285638, opcode: WRITE (16), nodeid: 1012555, insize: 8272, pid: 14041 Write 1012555 8192 266444800 unique: 285638, success, outsize: 24 unique: 285639, opcode: READ (15), nodeid: 1012554, insize: 80, pid: 14041 Read 1012554 131072 266452992 g_wrapper->Read(req, FuseId(ino), size, off, fi) failed: Get: invalid response code GeneralError (0x2002) unique: 285639, error: -5 (Input/output error), outsize: 16 unique: 285640, opcode: READ (15), nodeid: 1012554, insize: 80, pid: 14041 Read 1012554 131072 266584064 g_wrapper->Read(req, FuseId(ino), size, off, fi) failed: Get: invalid response code GeneralError (0x2002) unique: 285640, error: -5 (Input/output error), outsize: 16 unique: 285641, opcode: READ (15), nodeid: 1012554, insize: 80, pid: 14041 Read 1012554 4096 266452992 g_wrapper->Read(req, FuseId(ino), size, off, fi) failed: Get: invalid response code GeneralError (0x2002) unique: 285641, error: -5 (Input/output error), outsize: 16 unique: 285642, opcode: LOOKUP (1), nodeid: 3, insize: 49, pid: 14041 Lookup 3 sysiphus unique: 285642, success, outsize: 144 unique: 285643, opcode: LOOKUP (1), nodeid: 1009845, insize: 74, pid: 14041 Lookup 1009845 .home-16-05-17.tar.bz2.gpg.1CMgEo unique: 285643, success, outsize: 144 unique: 285644, opcode: UNLINK (10), nodeid: 1009845, insize: 74, pid: 14041 Unlink 1009845 .home-16-05-17.tar.bz2.gpg.1CMgEo unlinking inode 1012554 unique: 285645, opcode: OPENDIR (27), nodeid: 1, insize: 48, pid: 1580 unique: 285645, success, outsize: 32 unique: 285646, opcode: READDIR (28), nodeid: 1, insize: 80, pid: 1580 Readdir 1 4096 0 unique: 285644, success, outsize: 16 unique: 285646, success, outsize: 160 unique: 285647, opcode: LOOKUP (1), nodeid: 1009845, insize: 65, pid: 14041 Lookup 1009845 owncloud-db-04092015.sql unique: 285647, success, outsize: 144 unique: 285648, opcode: OPEN (14), nodeid: 1012529, insize: 48, pid: 14041 Open 1012529 unique: 285648, success, outsize: 32 unique: 285649, opcode: LOOKUP (1), nodeid: 1009845, insize: 73, pid: 14041 Lookup 1009845 .owncloud-db-04092015.sql.9ZSsWX unique: 285649, error: -2 (No such file or directory), outsize: 16 unique: 285650, opcode: MKNOD (8), nodeid: 1009845, insize: 89, pid: 14041 MakeNode 1009845 .owncloud-db-04092015.sql.9ZSsWX 0x00008180 creating object in storage 20001, parent: 00002675 unique: 285651, opcode: GETATTR (3), nodeid: 1, insize: 56, pid: 1580 GetAttr 1 new object id 12556 unique: 285650, success, outsize: 144 unique: 285651, success, outsize: 120
thats a lot on output. maybe i can pipe it into a file if you need more.
g_wrapper->Write(req, FuseId(ino), buf, size, off, fi) failed: timeout reaping usb urb
unique: 139, error: -5 (Input/output error), outsize: 16
weird. I can see no 2002 in debug.txt. Well, anyway. This timeouts is long-standing bug of AFT or kernel. I tried using usbmon on it, and it looks like URB arrives only when program exits, no matter how many time I wait for it. I'll try to replace polling with signal soon. Too bad I cannot reproduce it on my available devices/kernels
can you pull and test it, please? I added realtime signal in d115d88558d2eedba0e1719e8a0d4d173341e66e
mdomann@sysiphus:~$ uname -a Linux sysiphus 4.5.0-2-amd64 #1 SMP Debian 4.5.4-1 (2016-05-16) x86_64 GNU/Linux mdomann@sysiphus:~$ dpkg -l|grep fuse ii fuse 2.9.6-1 amd64 Filesystem in Userspace ii libfuse-dev 2.9.6-1 amd64 Filesystem in Userspace (development) ii libfuse2:amd64 2.9.6-1 amd64 Filesystem in Userspace (library) ii python-defusedxml 0.4.1-2 all XML bomb protection for Python stdlib modules (for Python 2)
the first file shows that is not mounted the second file is rather big but shows a lot of not transferred files
0x2002 usually indicates that it was generic exception, and it can be in adb logs. can you look at it, it'd be great help!
I got an idea. Maybe partial object reads will not succeed if they are out of object size, so read(buffersize) -> tail semantic does not work here. I need to look into android sources.
implemented safer size approach in 834c2cc61a81377419629ba07377444f99f3b413
please test
I just run rsync -vr --progress phone phone-backup and it worked flawlessly, too bad I cant reproduce it on my devices.
sadly it don't resolve all problems.
from phone to computer worked very well without problems.
from pc to phone starts at good speed but over the time it totally breaks and stopped.
mdomann@sysiphus:~$ rsync -rtva --progress /home/mdomann/media/owncloud/backup/sysiphus /mnt/z1c/SD-Karte/ sending incremental file list sysiphus/ sysiphus/duply.aes 15,326 100% 0.00kB/s 0:00:00 (xfr#1, to-chk=15/17) sysiphus/duply.tar.bz2.enc 144 100% 140.62kB/s 0:00:00 (xfr#2, to-chk=14/17) sysiphus/etc-16-05-12.tar.bz2.gpg 7,234,571 100% 659.60kB/s 0:00:10 (xfr#3, to-chk=13/17) sysiphus/etc-16-05-16.tar.bz2.gpg 7,441,946 100% 471.12kB/s 0:00:15 (xfr#4, to-chk=12/17) sysiphus/etc-16-05-17.tar.bz2.gpg 7,609,963 100% 761.20kB/s 0:00:09 (xfr#5, to-chk=11/17) sysiphus/etc-16-05-19.tar.bz2.gpg 7,756,399 100% 860.36kB/s 0:00:08 (xfr#6, to-chk=10/17) sysiphus/git.aes 6,329,790 100% 674.68kB/s 0:00:09 (xfr#7, to-chk=9/17) sysiphus/git.tar.bz2.enc 6,440,272 100% 602.08kB/s 0:00:10 (xfr#8, to-chk=8/17) sysiphus/gpg.aes 49,550 100% 47.25MB/s 0:00:00 (xfr#9, to-chk=7/17) sysiphus/home-16-05-12.tar.bz2.gpg 331,718,106 100% 4.93MB/s 0:01:04 (xfr#10, to-chk=6/17) sysiphus/home-16-05-16.tar.bz2.gpg 334,112,966 100% 147.58MB/s 0:00:02 (xfr#11, to-chk=5/17) sysiphus/home-16-05-17.tar.bz2.gpg 331,116,770 100% 224.59MB/s 0:00:01 (xfr#12, to-chk=4/17) sysiphus/home-16-05-19.tar.bz2.gpg 333,755,133 100% 197.94MB/s 0:00:01 (xfr#13, to-chk=3/17) sysiphus/owncloud-db-04092015.sql 665,474 100% 1.04MB/s 0:00:00 (xfr#14, to-chk=2/17) sysiphus/ssh.tar.bz2.enc 21,584 100% 34.50kB/s 0:00:00 (xfr#15, to-chk=1/17) sysiphus/sysiphus_packet.list 135,366 100% 216.36kB/s 0:00:00 (xfr#16, to-chk=0/17) rsync: write failed on "/mnt/z1c/SD-Karte/sysiphus/home-16-05-12.tar.bz2.gpg": Input/output error (5) rsync error: error in file IO (code 11) at receiver.c(393) [receiver=3.1.1]
the files are rather big too. so hopefully you find needed information.
i have build yesterday a cm-13.0 for my amami device. i will test this too.
did you pull before the latest run? I think I was right, and 2002 failures is about reading out of file, judging by your logs
Also, I just added releasing object edit session from Read. Can you test with it? no new logs needed at this point.
56e2978eeb2d38609118eb8289d4cd4d97f26abc
g_wrapper->Lookup(req, FuseId(parent), name) failed: timeout reaping usb urb unique: 273678, error: -5 (Input/output error), outsize: 16 unique: 273679, opcode: READDIR (28), nodeid: 1, insize: 80, pid: 1664 Readdir 1 4096 144 unique: 273679, success, outsize: 16 unique: 273680, opcode: GETATTR (3), nodeid: 1, insize: 56, pid: 1664 GetAttr 1 unique: 273680, success, outsize: 120 unique: 273681, opcode: OPENDIR (27), nodeid: 1, insize: 48, pid: 1664 unique: 273681, success, outsize: 32 unique: 273682, opcode: READDIR (28), nodeid: 1, insize: 80, pid: 1664 Readdir 1 4096 0 unique: 273682, success, outsize: 160 unique: 273683, opcode: LOOKUP (1), nodeid: 1, insize: 58, pid: 1664 Lookup 1 Interner Speicher 10006 ms since the last poll call g_wrapper->Lookup(req, FuseId(parent), name) failed: timeout reaping usb urb unique: 273683, error: -5 (Input/output error), outsize: 16 unique: 273684, opcode: LOOKUP (1), nodeid: 1, insize: 49, pid: 1664 Lookup 1 SD-Karte 10007 ms since the last poll call g_wrapper->Lookup(req, FuseId(parent), name) failed: timeout reaping usb urb unique: 273684, error: -5 (Input/output error), outsize: 16 unique: 273685, opcode: READDIR (28), nodeid: 1, insize: 80, pid: 1664 Readdir 1 4096 144 unique: 273685, success, outsize: 16 unique: 273686, opcode: GETATTR (3), nodeid: 1, insize: 56, pid: 1664 GetAttr 1 unique: 273686, success, outsize: 120 unique: 273687, opcode: WRITE (16), nodeid: 1013195, insize: 32848, pid: 1664 Write 1013195 32768 5865472 10009 ms since the last poll call g_wrapper->Write(req, FuseId(ino), buf, size, off, fi) failed: timeout reaping usb urb unique: 273687, error: -5 (Input/output error), outsize: 16 sadly the same probs
weird, this timeout thing again. What's the difference between this sessions? Different cables? Different usb ports? Different devices?
g_wrapper->Write(req, FuseId(ino), buf, size, off, fi) failed: timeout reaping usb urb unique: 173365, error: -5 (Input/output error), outsize: 16 unique: 173366, success, outsize: 120 unique: 173367, opcode: WRITE (16), nodeid: 1013240, insize: 131152, pid: 24448 Write 1013240 131072 199098368 unique: 173368, opcode: OPENDIR (27), nodeid: 1, insize: 48, pid: 1664 unique: 173368, success, outsize: 32 unique: 173369, opcode: READDIR (28), nodeid: 1, insize: 80, pid: 1664 Readdir 1 4096 0 10006 ms since the last poll call g_wrapper->Write(req, FuseId(ino), buf, size, off, fi) failed: timeout reaping usb urb unique: 173367, error: -5 (Input/output error), outsize: 16 unique: 173369, success, outsize: 160 unique: 173370, opcode: LOOKUP (1), nodeid: 3, insize: 49, pid: 24448 Lookup 3 sysiphus unique: 173370, success, outsize: 144 unique: 173371, opcode: LOOKUP (1), nodeid: 1009845, insize: 74, pid: 24448 Lookup 1009845 .home-16-05-17.tar.bz2.gpg.gHvH6b unique: 173371, success, outsize: 144 unique: 173372, opcode: UNLINK (10), nodeid: 1009845, insize: 74, pid: 24448 Unlink 1009845 .home-16-05-17.tar.bz2.gpg.gHvH6b unlinking inode 1013240 10009 ms since the last poll call terminate called after throwing an instance of 'mtp::usb::TimeoutException' what(): timeout reaping usb urb
different usb ports, different cables, different versions (usb2.0 / 3.0 ports) some time one sync is successsfully and the second one hangs up with time out. i don' have a second device to test. debug_phone2pc.txt
can you tie this timeout issue with cable? Mark cables with color tape probably and try to check if timeout errors occured only with one cable and not with another, etc. I've seen this issue on libusb mailing list, and they blame bad cables/port for it.
i have tried a selfbuild cm-13.0 and there are the same problems. phone 2 pc all right and pc 2 phone doesn't work. for now i have tried all possibles of cables and ports i can. i will ask a buddy of mine if he ca come around with his laptop.
Hey there, it takes me some time to get a laptop to test. lenovo thinkpad r400 if it matter. run debian stable. infos below.
root@tantalus-mobil:~# cat /etc/debian_version 8.4 root@tantalus-mobil:~# uname -a Linux tantalus-mobil 3.16.0-4-amd64 #1 SMP Debian 3.16.7-ckt25-2 (2016-04-08) x86_64 GNU/Linux root@tantalus-mobil:~#
root@tantalus-mobil:~# dpkg -l|grep fuse ii fuse 2.9.3-15+deb8u2 amd64 Filesystem in Userspace ii libfuse-dev 2.9.3-15+deb8u2 amd64 Filesystem in Userspace (development) ii libfuse2:amd64 2.9.3-15+deb8u2 amd64 Filesystem in Userspace (library)
seems to be that the problem persist but also look a bit different. i also tried different cables. hope to get some traces to find the problem.
can you run adb and get adb logs by chance? 2002 means something happened on java side
_wrapper->Read(req, FuseId(ino), size, off, fi) failed: Get: invalid response code GeneralError (0x2002)
unique: 2189, error: -5 (Input/output error), outsize: 16
i have build a new version with your latest commit.the android logs only contains lines like this. 2016-06-08-18-36-46.txt is there a possibility to raise the debug level for mtp?
D/MtpServer(13641): path: /storage/sdcard1/Downloads/cm-12.1-20160529-NIGHTLY-amami.zip parent: 17418 storageID: 00020001
rsync: read "/home/mdomann/z1c/SD-Karte/Downloads/.cm-12.1-20160529-NIGHTLY-amami.zip.tEYRdK": Input/output error (5) rsync: copy "/home/mdomann/z1c/SD-Karte/Downloads/.cm-12.1-20160529-NIGHTLY-amami.zip.tEYRdK" -> "Downloads/cm-12.1-20160529-NIGHTLY-amami.zip": Input/output error (5) rsync: read "/home/mdomann/z1c/SD-Karte/Downloads/.debian-8.4.0-amd64-CD-1.iso.y5uAj1": Input/output error (5) rsync: copy "/home/mdomann/z1c/SD-Karte/Downloads/.debian-8.4.0-amd64-CD-1.iso.y5uAj1" -> "Downloads/debian-8.4.0-amd64-CD-1.iso": Input/output error (5)
sent 959,461,359 bytes received 989 bytes 2,129,772.14 bytes/sec total size is 1,228,609,810 speedup is 1.28 rsync error: some files/attrs were not transferred (see previous errors) (code 23) at main.c(1183) [sender=3.1.1]
unique: 144247, opcode: WRITE (16), nodeid: 1017556, insize: 8272, pid: 3119 Write f86d4 2000 15f18000 unique: 144247, success, outsize: 24 unique: 144248, opcode: WRITE (16), nodeid: 1017556, insize: 8272, pid: 3119 Write f86d4 2000 15f1a000 unique: 144248, success, outsize: 24 unique: 144249, opcode: READ (15), nodeid: 1017555, insize: 80, pid: 3119 Read f86d3 20000 15f1c000 g_wrapper->Read(req, FuseId(ino), size, off, fi) failed: Get: invalid response code GeneralError (0x2002) unique: 144249, error: -5 (Input/output error), outsize: 16 unique: 144250, opcode: READ (15), nodeid: 1017555, insize: 80, pid: 3119 Read f86d3 20000 15f3c000 g_wrapper->Read(req, FuseId(ino), size, off, fi) failed: Get: invalid response code GeneralError (0x2002) unique: 144250, error: -5 (Input/output error), outsize: 16 unique: 144251, opcode: READ (15), nodeid: 1017555, insize: 80, pid: 3119 Read f86d3 1000 15f1c000 g_wrapper->Read(req, FuseId(ino), size, off, fi) failed: Get: invalid response code GeneralError (0x2002) unique: 144251, error: -5 (Input/output error), outsize: 16 unique: 144252, opcode: LOOKUP (1), nodeid: 3, insize: 50, pid: 3119 Lookup 3 Downloads unique: 144252, success, outsize: 144 unique: 144253, opcode: LOOKUP (1), nodeid: 1017418, insize: 76, pid: 3119 Lookup f864a .debian-8.4.0-amd64-CD-1.iso.y5uAj1 unique: 144253, success, outsize: 144 unique: 144254, opcode: UNLINK (10), nodeid: 1017418, insize: 76, pid: 3119 Unlink f864a .debian-8.4.0-amd64-CD-1.iso.y5uAj1 unlinking inode f86d3 unique: 144254, success, outsize: 16 unique: 144255, opcode: GETATTR (3), nodeid: 1017418, insize: 56, pid: 3118 GetAttr f864a unique: 144255, success, outsize: 120 unique: 144256, opcode: SETATTR (4), node
I don't know, I always thought that adb does not filter anything by default, it's always noisy
I added more logs in Read/Write, can you check with 04e51991421fdd5924a04bf6fa0c5fbaa00e536d?
g_wrapper->Write(req, FuseId(ino), buf, size, off, fi) failed: timeout reaping usb urb unique: 44616, error: -5 (Input/output error), outsize: 16 unique: 44617, opcode: WRITE (16), nodeid: 1017583, insize: 131152, pid: 2830 Write 1017583 131072 115081216 10010 ms since the last poll call g_wrapper->Write(req, FuseId(ino), buf, size, off, fi) failed: timeout reaping usb urb unique: 44617, error: -5 (Input/output error), outsize: 16 unique: 44618, opcode: UNLINK (10), nodeid: 1017418, insize: 76, pid: 2830 Unlink 1017418 .debian-8.4.0-amd64-CD-1.iso.TgjdGH unlinking inode 1017583 10010 ms since the last poll call terminate called after throwing an instance of 'mtp::usb::TimeoutException' what(): timeout reaping usb urb
the file contains
06-09 19:54:12.604 D/MtpServer(28941): path: /storage/sdcard1/Downloads/.debian-8.4.0-amd64-CD-1.iso.TgjdGH parent: 17418 storageID: 00020001 06-09 19:54:42.446 E/MtpRequestPacket(28941): Malformed MTP request packet
but not really helpfull i think
log lones I was interested of were before this line :)
g_wrapper->Write(req, FuseId(ino), buf, size, off, fi) failed: timeout reaping usb urb
can you send me debug output of aft-mtp-mount before failing write?
Thanks, you've been the most helpful. It looks like the only place triggering timeout now is readdir. I will fix it tomorrow.
Increased timeout for GetPropertyList operations in 52e17433ab8230025faf109387a7e3c9ffb355ef I have issue #46 about removing any timeouts in next version, so I'll fix it eventually. let me know if it helps
i have been for holidays :-) tested now:
Write 1004403 131072 142999552 truncating file to 143130624 unique: 333867, success, outsize: 24 unique: 333868, opcode: WRITE (16), nodeid: 1004403, insize: 131152, pid: 27609 Write 1004403 131072 143130624 truncating file to 143261696 10003 ms since the last poll call g_wrapper->Write(req, FuseId(ino), buf, size, off, fi) failed: timeout reaping usb urb unique: 333868, error: -5 (Input/output error), outsize: 16 unique: 333869, opcode: WRITE (16), nodeid: 1004403, insize: 131152, pid: 27609 Write 1004403 131072 143130624 unique: 333870, opcode: OPENDIR (27), nodeid: 1, insize: 48, pid: 1588 unique: 333870, success, outsize: 32 unique: 333871, opcode: READDIR (28), nodeid: 1, insize: 80, pid: 1588 Readdir 1 4096 0 10004 ms since the last poll call g_wrapper->Write(req, FuseId(ino), buf, size, off, fi) failed: timeout reaping usb urb unique: 333869, error: -5 (Input/output error), outsize: 16 unique: 333871, success, outsize: 160 unique: 333873, opcode: LOOKUP (1), nodeid: 1, insize: 58, pid: 1588 unique: 333872, opcode: UNLINK (10), nodeid: 1003294, insize: 74, pid: 27609 Unlink 1003294 .home-16-06-03.tar.bz2.gpg.lSG04s unlinking inode 1004403 Lookup 1 Interner Speicher 10007 ms since the last poll call terminate called after throwing an instance of 'mtp::usb::TimeoutException' what(): timeout reaping usb urb
now tested on my desktop since i have to give the laptop back the log on the android device says at least point:
Malformed MTP request packet server is null in send_object_removed
Thanks a lot!
Malformed MTP request packet server is null in send_object_removed
That's interesting, I will look into android sources.
Well, anyway. This timeouts is long-standing bug of AFT or kernel. I tried using usbmon on it, and it looks like URB arrives only when program exits, no matter how many time I wait for it.
Hi,
I saw similar behavior on a full speed USB device. What are the payload sizes of such URBs?
What are the payload sizes of such URBs?
sizes are different really, if you suspected missing ZLP, it's not the case! :P
I had similar errors (https://gist.github.com/Sindarus/b724df384af18f917e0affab6f409308) and solved the issue by using a different USB cable. I could determine that the first USB cable was faulty by testing it on a different computer running windows.
