GNOME Bugzilla – Bug 784477
gvfs-mtp hangs after seeking more than 4096 bytes into an empty file
Last modified: 2017-11-20 16:03:35 UTC
gvfs-mtp hangs if a program seeks >= 4096 bytes into an empty (0 byte) file and then reads at least one byte. Used gvfs 1.28.3 and gvfs 1.32.1 on openSUSE 42.2 Linux. Tested with different Android devices: - Samsung Galaxy S4 Mini (i9195), running LineageOS 14.1 (Android 7.1.2) - Alcatel OneTouch 997d (Android 4.1.1) = Example with dd = cmd: dd if=/run/user/1000/gvfs/mtp.../sdcard/0k_file.txt bs=1 skip=4096 count=1 strace of dd hangs here: [...] lseek(0, 4096, SEEK_CUR) = 4096 [...] read(0, note: If I do skip=4095 or count=0 the bug is not triggered. = Example with 7z (version 9.20) = cmd: 7z x /run/user/1000/gvfs/mtp.../sdcard/0k_file.zip strace of 7z hangs here (7z thread 2 of 2): [...] lseek(3, 32768, SEEK_CUR) = 32768 read(3, = gvfs-mtp = In the meanwhile, strace of the two most active gvfs-mtp threads loops this: = gvfs-mtp 8427 = [...] futex(0x7f64f4007a68, FUTEX_WAIT_PRIVATE, 2, NULL) = 0 futex(0x7f64f4007a68, FUTEX_WAKE_PRIVATE, 1) = 0 timerfd_settime(13, TFD_TIMER_ABSTIME, {it_interval={0, 0}, it_value={56242, 383996000}}, NULL) = 0 ioctl(14, USBDEVFS_SUBMITURB, 0x7f64f4021e20) = 0 poll([{fd=11, events=POLLIN}, {fd=13, events=POLLIN}, {fd=14, events=POLLOUT}], 3, 60000) = 1 ([{fd=14, revents=POLLOUT}]) ioctl(14, USBDEVFS_REAPURBNDELAY, 0x7f65077fd528) = 0 timerfd_settime(13, 0, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0 ioctl(14, USBDEVFS_REAPURBNDELAY, 0x7f65077fd528) = -1 EAGAIN (Resource temporarily unavailable) futex(0x7f64f4007a94, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x7f64f4007a68, 76030) = 1 timerfd_settime(13, TFD_TIMER_ABSTIME, {it_interval={0, 0}, it_value={56242, 384139000}}, NULL) = 0 ioctl(14, USBDEVFS_SUBMITURB, 0x7f64f4021950) = 0 futex(0x7f64f4007a94, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 76031, {1499088954, 867619560}, ffffffff) = 0 futex(0x7f64f4007a68, FUTEX_WAKE_PRIVATE, 1) = 0 timerfd_settime(13, TFD_TIMER_ABSTIME, {it_interval={0, 0}, it_value={56242, 384292000}}, NULL) = 0 ioctl(14, USBDEVFS_SUBMITURB, 0x7f64f4022ef0) = 0 futex(0x7f64f4007a94, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 76033, {1499088954, 867756349}, ffffffff) = 0 futex(0x7f64f4007a68, FUTEX_WAKE_PRIVATE, 1) = 0 timerfd_settime(13, TFD_TIMER_ABSTIME, {it_interval={0, 0}, it_value={56242, 384428000}}, NULL) = 0 ioctl(14, USBDEVFS_SUBMITURB, 0x7f64f4021e80) = 0 futex(0x7f64f4007a94, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 76035, {1499088954, 867890923}, ffffffff) = 0 futex(0x7f64f4007a68, FUTEX_WAIT_PRIVATE, 2, NULL) = 0 futex(0x7f64f4007a68, FUTEX_WAKE_PRIVATE, 1) = 0 timerfd_settime(13, TFD_TIMER_ABSTIME, {it_interval={0, 0}, it_value={56242, 384587000}}, NULL) = 0 ioctl(14, USBDEVFS_SUBMITURB, 0x7f64f4026990) = 0 poll([{fd=11, events=POLLIN}, {fd=13, events=POLLIN}, {fd=14, events=POLLOUT}], 3, 60000) = 1 ([{fd=14, revents=POLLOUT}]) ioctl(14, USBDEVFS_REAPURBNDELAY, 0x7f65077fd528) = 0 timerfd_settime(13, 0, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0 ioctl(14, USBDEVFS_REAPURBNDELAY, 0x7f65077fd528) = -1 EAGAIN (Resource temporarily unavailable) futex(0x7f64f4007a94, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x7f64f4007a68, 76038) = 1 timerfd_settime(13, TFD_TIMER_ABSTIME, {it_interval={0, 0}, it_value={56242, 384934000}}, NULL) = 0 ioctl(14, USBDEVFS_SUBMITURB, 0x7f64f4020640) = 0 = gvfs-mtp 8388 = [...] futex(0x7f64f401bb18, FUTEX_WAIT_PRIVATE, 2, NULL) = 0 futex(0x7f64f401bb18, FUTEX_WAKE_PRIVATE, 1) = 0 timerfd_settime(13, 0, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0 ioctl(14, USBDEVFS_REAPURBNDELAY, 0x7f65067fbcf8) = -1 EAGAIN (Resource temporarily unavailable) futex(0x7f64f4007a94, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x7f64f4007a68, 75906) = 1 futex(0x7f64f4007a68, FUTEX_WAKE_PRIVATE, 1) = 0 poll([{fd=11, events=POLLIN}, {fd=13, events=POLLIN}, {fd=14, events=POLLOUT}], 3, 3600000) = 1 ([{fd=14, revents=POLLOUT}]) ioctl(14, USBDEVFS_REAPURBNDELAY, 0x7f65067fbcf8) = 0 timerfd_settime(13, 0, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0 ioctl(14, USBDEVFS_REAPURBNDELAY, 0x7f65067fbcf8) = -1 EAGAIN (Resource temporarily unavailable) futex(0x7f64f4007a94, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x7f64f4007a68, 75908) = 1 futex(0x7f64f4007a68, FUTEX_WAKE_PRIVATE, 1) = 0 poll([{fd=11, events=POLLIN}, {fd=13, events=POLLIN}, {fd=14, events=POLLOUT}], 3, 3600000) = 1 ([{fd=14, revents=POLLOUT}]) ioctl(14, USBDEVFS_REAPURBNDELAY, 0x7f65067fbcf8) = 0 timerfd_settime(13, 0, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0 ioctl(14, USBDEVFS_REAPURBNDELAY, 0x7f65067fbcf8) = -1 EAGAIN (Resource temporarily unavailable) futex(0x7f64f4007a94, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x7f64f4007a68, 75910) = 1 futex(0x7f64f4007a68, FUTEX_WAKE_PRIVATE, 1) = 0 poll([{fd=11, events=POLLIN}, {fd=13, events=POLLIN}, {fd=14, events=POLLOUT}], 3, 3600000) = 1 ([{fd=14, revents=POLLOUT}]) ioctl(14, USBDEVFS_REAPURBNDELAY, 0x7f65067fbcf8) = 0 timerfd_settime(13, 0, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0 ioctl(14, USBDEVFS_REAPURBNDELAY, 0x7f65067fbcf8) = -1 EAGAIN (Resource temporarily unavailable) futex(0x7f64f4007a94, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x7f64f4007a68, 75912) = 1 futex(0x7f64f4007a68, FUTEX_WAKE_PRIVATE, 1) = 0 poll([{fd=11, events=POLLIN}, {fd=13, events=POLLIN}, {fd=14, events=POLLOUT}], 3, 3600000) = 1 ([{fd=14, revents=POLLOUT}]) ioctl(14, USBDEVFS_REAPURBNDELAY, 0x7f65067fbcf8) = 0 timerfd_settime(13, 0, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0 ioctl(14, USBDEVFS_REAPURBNDELAY, 0x7f65067fbcf8) = -1 EAGAIN (Resource temporarily unavailable) futex(0x7f64f4007a94, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x7f64f4007a68, 75914) = 1 futex(0x7f64f4007a68, FUTEX_WAKE_PRIVATE, 1) = 0 poll([{fd=11, events=POLLIN}, {fd=13, events=POLLIN}, {fd=14, events=POLLOUT}], 3, 3600000) = 1 ([{fd=14, revents=POLLOUT}]) ioctl(14, USBDEVFS_REAPURBNDELAY, 0x7f65067fbcf8) = 0 futex(0x7f64f401bb18, FUTEX_WAIT_PRIVATE, 2, NULL) = 0 futex(0x7f64f401bb18, FUTEX_WAKE_PRIVATE, 1) = 0 timerfd_settime(13, 0, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0 ioctl(14, USBDEVFS_REAPURBNDELAY, 0x7f65067fbcf8) = -1 EAGAIN (Resource temporarily unavailable) futex(0x7f64f4007a94, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x7f64f4007a68, 75916) = 1 futex(0x7f64f4007a68, FUTEX_WAKE_PRIVATE, 1) = 0 poll([{fd=11, events=POLLIN}, {fd=13, events=POLLIN}, {fd=14, events=POLLOUT}], 3, 3600000) = 1 ([{fd=14, revents=POLLOUT}])
Digging through old bugs here. Is this still happening? I wonder if the fix for bug 785391 might have helped here, by making the sockets non-blocking.
(In reply to Philip Langdale from comment #1) > Digging through old bugs here. Is this still happening? I wonder if the fix > for bug 785391 might have helped here, by making the sockets non-blocking. Just tested with https://download.opensuse.org/tumbleweed/iso/openSUSE-Tumbleweed-GNOME-Live-x86_64-Snapshot20171102-Media.iso which comes with: - gvfs-backends-1.34.1 - gvfs-1.34.1 - gvfs-fuse-1.34.1 - glib2-tools-2.54.2 Bug is still there! Last post in bug 785391 is on 2017-08-18, mentioning the commit 04962708 which is included in gvfs-1.34.1. gvfs-1.34.1 was released on 2017-10-02. https://git.gnome.org/browse/gvfs/commit/?id=0496270 https://git.gnome.org/browse/gvfs/tree/daemon/gvfschannel.c?h=1.34.1#n213
Hmm, I can reproduce, but seems rather like a bug in libmtp: $ gstack $(pidof /opt/gnome/libexec/gvfsd-mtp)
+ Trace 238143
Thread 6 (Thread 0x7f8dbac3a700 (LWP 1848))
Philip?
I'll take a look. What are the POSIX semantics for this? Should both the seek and the read fail? I'll look it up when I get a chance, but it seems like the problem is that we should be returning an error for both operations and are not doing so.
We should fail on seek if it is opened for reading and somebody tries to seek out of range... You can try POSIX semantics easily: $ touch ~/empty $ dd if=~/empty bs=1 skip=4095 count=1 dd: /home/oholy/empty: cannot skip to specified offset 0+0 records in 0+0 records out 0 bytes copied, 0.000172526 s, 0.0 kB/s
Conducted a test with simple-mtpfs, which is also based on libmtp. https://github.com/phatina/simple-mtpfs Tested with - simple-mtpfs 0.2 from openSUSE 42.3 OSS repo - simple-mtpfs 0.3 build on openSUSE 42.3 from source In both cases dd aborted correctly and didn't hang. So it's probably not a libmtp bug (or at least not only a libmtp bug). dd if=/mnt/0k_file.txt bs=1 skip=4096 count=1 lseek(0, 0, SEEK_CUR) = 0 ioctl(0, MTIOCGET, 0x7ffcd9a44e20) = -1 ENOSYS (Function not implemented) lseek(0, 4096, SEEK_CUR) = 4096 fstat(0, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0 read(0, "", 1) = 0 close(0) = 0 http://man7.org/linux/man-pages/man2/read.2.html Looks like read simply returns 0 bytes and that's it. It's also what the read (2) manpage says: | On files that support seeking, the read operation commences at | the current file offset, and the file offset is incremented by | the number of bytes read. If the current file offset is at or | past the end of file, no bytes are read, and read() | returns zero. http://man7.org/linux/man-pages/man2/lseek.2.html You may also want to overlook the lseek behavior. | The lseek() function allows the file offset to be set beyond | the end of the file (but this does not change the size of the | file). If data is later written at this point, subsequent | reads of the data in the gap (a "hole") return null bytes | ('\0') until data is actually written into the gap.
Note that simple-mtpfs doesn't implement the direct I/O extensions so seeking never works - that's what you get ENOSYS. The issue here is that nothing in libmtp generates errors in this scenario and I assumed it would. So gvfs-mtp needs to enforce the file size constraints and generate the errors itself
Can you give me an exact repro case? I can't reproduce it here. $ cd /run/user/1000/gvfs/mtp:host=%5Busb%3A003%2C004%5D/Internal shared storage/Download $ touch empty $ dd if=empty of=/dev/null bs=1 count=1 skip=4096 dd: empty: cannot skip to specified offset dd: error reading 'empty': Input/output error 0+0 records in 0+0 records out 0 bytes copied, 0.00475822 s, 0.0 kB/s I'd say this might be device-side bug that was fixed, but Ondrej is running 8.1 beta on his test device, IIRC and I'm running 8.0.
The steps you mentioned should be enough, hmm, I will try to find some time to debug what is happening there...
(In reply to Philip Langdale from comment #7) > Note that simple-mtpfs doesn't implement the direct I/O extensions so > seeking never works - that's what you get ENOSYS. Sadly I don't have an Android 8/Oreo device. And all other MTP devices I have aren't usable with gvfs because of this bug. https://bugzilla.gnome.org/show_bug.cgi?id=773824
Created attachment 363358 [details] [review] Patch to implement our own EOF check I still feel like I don't understand the boundaries of the problem here. md: in this bug, you mention two android devices, but in bug 773824, you mention a Nokia device and that GetPartialObject (not the 64 android variant) support was relevant to you. I can readily believe there might be a big difference between the AOSP mtp stack and custom OEM ones, but anything running Lineage should be AOSP, and I'm sceptical that there is a problem there, given that I never saw this over the years and multiple AOSP versions. Obviously, Ondrej's report of a failure with 8.1 beta is confusing in that regard. Anyway, I'm attaching a patch that does the EOF check. Please try it out. I'm not comfortable committing it as-is, because, in general, we should be trying to let the device handle this behaviour, so I want to better understand where we see problems vs where we don't.
(In reply to Philip Langdale from comment #11) > [...] > I still feel like I don't understand the boundaries of the problem here. md: > in this bug, you mention two android devices, but in bug 773824, you mention > a Nokia device and that GetPartialObject (not the 64 android variant) > support was relevant to you. Just forget about my mentioning of bug 773824 here :-) It's not really relevant. > I can readily believe there might be a big difference between the AOSP mtp > stack and custom OEM ones, but anything running Lineage should be AOSP, Sounds reasonable to me. > and I'm sceptical that there is a problem there, given that I never saw > this over the years and multiple AOSP versions. Obviously, Ondrej's report > of a failure with 8.1 beta is confusing in that regard. I've tested with two devices to be sure it's not a device specific bug. Remember: Only my Samsung Galaxy S4 Mini (i9195) runs LineageOS. My other device, the Alcatel OneTouch 997d, runs the vendors original Android 4.1.1. I just did two more tests: - Samsung Galaxy S4 Mini (i9195), booted into TWRP recovery 3.1.1-0-0. (tested with a file on the internal storage and for a file on the sdcard) - My new "Fairphone 2", running LineageOS-14.1. (tested with a file on the internal storage) In all cases the bug was reproducible. With Ondrejs device it's four devices showing the bug. So that's probably the usual case and your device is somehow the lucky case. > Anyway, I'm attaching a patch that does the EOF check. Please try it out. Compiled for openSUSE 42.3 with gvfs-1.28.3 https://download.opensuse.org/repositories/home:/duge_at_pre-sense_de:/branches:/openSUSE:/Leap:/42.3:/Update/standard/x86_64/ https://build.opensuse.org/package/show/home:duge_at_pre-sense_de:branches:openSUSE:Leap:42.3:Update/gvfs Result: Solves the bug. Thanks!!! > I'm not comfortable committing it as-is, because, in general, we should be > trying to let the device handle this behaviour, so I want to better > understand where we see problems vs where we don't. Understandable and I'll try to help finding the real cause. But if we can't find a more specific cause, I'd be very glad if you commit your patch. Because in the end it wouldn't be nice to let the user alone with a problem which is reproducible on multiple different devices.
Review of attachment 363358 [details] [review]: I can confirm that the patch successfully workaround the issues, I am ok with it, but would be nice to check libmtp code for a potential bug, or if it can't be handled better there. See the following log with LIBMTP_DEBUG=99... mtp: Added new job source 0x7f21900130c0 (GVfsReadChannel) mtp: (I) do_open_for_read done. fuse(17605): vfs_open: -> Success fuse(17605): vfs_read: /mtp:host=%5Busb%3A002%2C033%5D/Intern? sd?len? ?lo?i?t?/TEST fuse(17605): setup_input_stream: have stream fuse(17605): setup_input_stream: doing read fuse(17605): read_stream: seeking to offset 4096. mtp: Queued new job 0x7f218802d860 (GVfsJobSeekRead) mtp: (I) do_seek_on_read (2767 0 4096 1) mtp: send_reply(0x7f218802d860), pos=4096, failed=0 () mtp: (I) do_seek_on_read done. (4096) mtp: Queued new job 0x5568210c2ee0 (GVfsJobRead) mtp: (I) do_read (2767 4096 4096) mtp: (I) check_event: Polling for events. mtp: (I) check_event: Polling for events. mtp: (I) check_event: Polling for events. mtp: (I) check_event: Polling for events. mtp: (I) check_event: Polling for events. ptp_usb_getresp: detected short response of 0 bytes, expect problems! (re-reading response), rlen mtp: (I) check_event: Polling for events. ptp_usb_getresp: detected short response of -2147475632 bytes, expect problems! (re-reading response), rlen mtp: (I) check_event: Polling for events. ptp_usb_getresp: detected short response of -2147475632 bytes, expect problems! (re-reading response), rlen mtp: (I) check_event: Polling for events. ptp_usb_getresp: detected short response of -2147475632 bytes, expect problems! (re-reading response), rlen mtp: (I) check_event: Polling for events. ptp_usb_getresp: detected short response of -2147475632 bytes, expect problems! (re-reading response), rlen mtp: (I) check_event: Polling for events. ... The -2147475632 looks pretty weird, there is %d specifier for unsigned long, but anyway: https://github.com/libmtp/libmtp/blob/master/src/libusb-glue.c#L1486
Created attachment 363852 [details] [review] Patch to implement our own EOF check v2 Updated patch to additionally do a check for partial read past EOF and truncate if necessary
I have pushed the fix to master. Should we backport to any branches?
Thanks, please push it in gnome-3-26 as well.
Done