diegoe commented 4 years ago

Describe the bug libgphoto2 stalls when querying a locked iPhone6.

Name the camera Apple iPhone 5 (PTP mode) usb:001,016

libgphoto2 and gphoto2 version gphoto2 2.5.23.1 gcc, popt(m), exif, no cdk, no aa, jpeg, readline libgphoto2 2.5.24.1 standard camlibs, gcc, ltdl, EXIF libgphoto2_port 0.12.0 iolibs: disk ptpip serial usb1 usbdiskdirect usbscsi, gcc, ltdl, EXIF, USB, serial without locking

To Reproduce I ran into this bug while debugging a long login time in GNOME sessions while my iPhone was plugged and locked. The delays in login time were noticeable and always stalling in gvfs' gphoto2 volume monitor backend.

After some investigation I found out that camlibs/ptp2 has special-case'd Apple devices in light of the locked/unlocked behavior of not allowing access to files unless unlocked:

8732     if (a.usb_vendor == 0x05ac) {   /* Apple iOS 10.2 hack */
8733         int         timeout;
8734         PTPContainer    event;
8735 
8736         /* Background:
8737          * Untrusted computer gets a storage id of 0xfeedface.
8738          * Once the ipad user allows / trusts the computer in a popup dialog,
8739          * this storage removed and the actual storage is being addded
8740          * StoreRemoved 0xfeedface and StoreAdded 0x.... events are seen.
8741          */
8742 
8743         /* Wait for a valid storage id , starting with 0x0001???? */
8744         /* wait for 3 events or 9 seconds at most */
8745         tries = 3;
8746         gp_port_get_timeout (camera->port, &timeout);
8747         gp_port_set_timeout (camera->port, 3000);
8748         while (tries--) {
8749             /* 0xfeedface and 0x00000000 seem bad storageid values for iPhones */
8750             /* The event handling code in ptp.c will refresh the storage list if
8751              * it sees the correct events */
8752             if (params->storageids.n && (
8753                 (params->storageids.Storage[0] != 0xfeedface) &&
8754                 (params->storageids.Storage[0] != 0x00000000)
8755             ))
8756                 break;
8757             C_PTP_REP (ptp_wait_event (params));
8758             while (ptp_get_one_event (params, &event)) {
8759                 GP_LOG_D ("Initial ptp event 0x%x (param1=%x)", event.Code, event.Param1);
8760                 /* the ptp stack should refresh the storage array */
8761                 if (event.Code == PTP_EC_StoreAdded)
8762                     break;
8763             }
8764         }
8765         gp_port_set_timeout (camera->port, timeout);
8766     }

This behavior translates into almost 18 seconds of overhead in my system (see attached logs). Even more, anything waiting on camera_init() stalls, as ptp_wait_event() seems to be 100% sync.

I believe this might be a left over of older iOS behavior with respect to the locked/unlocked flow. If my iPhone is locked, I expect my application (gphoto2 cli, or GNOME, or etc) to report said thing instead of mysteriously stalling for 20 seconds. On macOS, non-gphoto2 apps simply omit the iPhone as a source, and some report "Unlock your iPhone to see photos". I believe this behavior is more reasonable.

I'm admittedly not super familiar with libgphoto2 code, but I would propose that said ptp_wait_event be changed to ptp_queue_event so that it doesn't stall. I guess ptp_check_event should work too, but you get the idea.

I'm attaching logs for the behavior of gphoto2 on master, with my changes, and in both cases with the iPhone locked/unlocked.

Reference: https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=942832

Current master behavior

🍄 [22:55:27]libertad:install:master$ gphoto2 --debug  --storage-info --debug-logfile=iphone6-locked.log 
[Storage 0]                                                                    
label=Internal Storage
description=Internal Storage
basedir=/store_feedface
access=0 Read-Write
type=3 Fixed RAM
fstype=3 Camera layout (DCIM)
totalcapacity=15625000 KB
free=3361960 KB
freeimages=2295

🍄 [22:56:05]libertad:install:master$ gphoto2 --debug  --storage-info --debug-logfile=iphone6-unlocked.log 
[Storage 0]                                                                    
label=Internal Storage
description=Internal Storage
basedir=/store_00010001
access=0 Read-Write
type=3 Fixed RAM
fstype=3 Camera layout (DCIM)
totalcapacity=15625000 KB
free=3361960 KB
freeimages=2295

🍄 [23:36:07]libertad:install:master$ tail  -n1 iphone6*log
==> iphone6-locked.log <==
18.108241 recurse_delete_folder       (2): Recurse delete folder 0x5639496e28c0//

==> iphone6-unlocked.log <==
0.104276 recurse_delete_folder       (2): Recurse delete folder 0x55a777bcc8c0//

With ptp_queue_event

🍄 [23:24:08]libertad:install:master$ LD_LIBRARY_PATH=/home/diegoe/gnome/libgphoto2/install/lib/ bin/gphoto2 --debug  --storage-info --debug-logfile=iphone6-locked-queue-event.log
[Storage 0]                                                                    
label=Internal Storage
description=Internal Storage
basedir=/store_feedface
access=0 Read-Write
type=3 Fixed RAM
fstype=3 Camera layout (DCIM)
totalcapacity=15625000 KB
free=3353396 KB
freeimages=2289

🍄 [23:24:27]libertad:install:master$ LD_LIBRARY_PATH=/home/diegoe/gnome/libgphoto2/install/lib/ bin/gphoto2 --debug  --storage-info --debug-logfile=iphone6-unlocked-queue-event.log
[Storage 0]                                                                    
label=Internal Storage
description=Internal Storage
basedir=/store_00010003
access=0 Read-Write
type=3 Fixed RAM
fstype=3 Camera layout (DCIM)
totalcapacity=15625000 KB
free=3353396 KB
freeimages=2289

🍄 [23:36:07]libertad:install:master$ tail  -n1 iphone6*log
==> iphone6-locked-queue-event.log <==
0.101341 delete_all_files            (2): Delete all files in folder 0x561a735a7900//

==> iphone6-unlocked-queue-event.log <==
0.099206 delete_all_files            (2): Delete all files in folder 0x555f73a8f900//

Logs

iphone6-locked: https://gist.github.com/diegoe/f3d941a3e5c92927e98fcdb1912dd4d8
iphone6-unlocked: https://gist.github.com/diegoe/c2321728f2ad5506079bb85d81895725
iphone6-queue-locked: https://gist.github.com/diegoe/bb92d774c6498feb7323f2574b3ba8c5
iphone6-queue-unlocked: https://gist.github.com/diegoe/666056dc4cc2b5d8a102add13d5b8ff1

diegoe commented 4 years ago

Some further investigation has led me to believe that this issue is specifically triggered as follows:

Connect the iPhone to the MacBook under macOS, unlock it. The iPhone now trusts the MacBook.
Reboot into Linux.
The iPhone still "trusts" the MacBook, but the timeout/stalling in gphoto2 happens

If you trigger a "lock down" in the iPhone (pressing lock multiple times to make it forget recently trusted USB devices) -- you can eliminate the stalling. Alternatively, you can directly boot into Linux.

It appears that the iPhone exposes more of its information when it "trusts" the MacBook. For example, in the scenario above, I can --auto-detect the iPhone. However, if I directly boot into Linux or trigger a "lock down", I can't.

My hypothesis is that the iPhone believes that Linux is still the same system as when it authorized macOS, but libgphoto2 is somehow not meeting some expectation in the conversation. This could be argued as an issue with the lock/unlock feature of the iPhone, but I believe that the original question is still valid: should libgphoto2 stall for so long when there's some kind of broken back and forth with an iOS device? Perhaps the quirk in that part of the code needs to be updated?

corsac-s commented 4 years ago

3. The iPhone still "trusts" the MacBook, but the timeout/stalling in gphoto2 happens
Commenting about this part (with my libimobiledevice Debian maintainer background and as an iPhone user on Linux): this is not how iPhone pairing works. The authentication/pairing is done with a daemon running on the host (whether MacOS/iTunes or Linux/usbmuxd), so pairing on MacOS and rebooting on Linux should give an “unpaired” iPhone anyway.

Note that USB restricted mode on recent iOS can also alter the behavior: before first passcode entry or the “lock down” you mention (for example entering SOS mode and cancelling it) means the USB device won't even appear to Linux.

hadess commented 4 years ago

Is libgphoto2 waiting for usbmuxd pairing (eg. trust), or for a screen unlock?

If the former, it might be possible to only create the volumes (and try to mount those volumes) in gvfs/GNOME when the pairing has already been done.

diegoe commented 4 years ago

Today I was having delays on session login so I tried again to reproduce with gphoto2 on the command line.

I also stopped the system's usbmuxd and ran /usr/sbin/usbmuxd --user usbmux --systemd -v to monitor for anything weird, but it doesn't seem to be stalling on anything from usbmuxd:

[21:18:10.815][4] Client 14 is going to be disconnected: /usr/libexec/upowerd[1183]
[21:18:10.886][4] Client 13 is going to be disconnected: /usr/libexec/upowerd[1183]
[21:20:10.789][4] Client 13 accepted: /usr/libexec/upowerd[1183]
[21:20:10.790][4] Client connected to device 1 (9->62078)
[21:20:10.792][4] Client 14 accepted: /usr/libexec/upowerd[1183]
[21:20:10.792][4] Client 14 connection closed
[21:20:10.793][4] Client 14 is going to be disconnected: /usr/libexec/upowerd[1183]
[21:20:10.793][4] Client 14 accepted: /usr/libexec/upowerd[1183]
[21:20:10.793][4] Client 14 connection closed
[21:20:10.793][4] Client 14 is going to be disconnected: /usr/libexec/upowerd[1183]
[21:20:10.800][4] Client 14 accepted: /usr/libexec/upowerd[1183]
[21:20:10.800][4] Client 14 connection closed
[21:20:10.800][4] Client 14 is going to be disconnected: /usr/libexec/upowerd[1183]
[21:20:10.874][4] Client 13 is going to be disconnected: /usr/libexec/upowerd[1183]
[21:22:10.773][4] Client 13 accepted: /usr/libexec/upowerd[1183]
[21:22:10.775][4] Client connected to device 1 (10->62078)
[21:22:10.777][4] Client 14 accepted: /usr/libexec/upowerd[1183]
[21:22:10.778][4] Client 14 connection closed
[21:22:10.778][4] Client 14 is going to be disconnected: /usr/libexec/upowerd[1183]
[21:22:10.778][4] Client 14 accepted: /usr/libexec/upowerd[1183]
[21:22:10.779][4] Client 14 connection closed
[21:22:10.779][4] Client 14 is going to be disconnected: /usr/libexec/upowerd[1183]
[21:22:10.789][4] Client 14 accepted: /usr/libexec/upowerd[1183]
[21:22:10.790][4] Client 14 connection closed
[21:22:10.790][4] Client 14 is going to be disconnected: /usr/libexec/upowerd[1183]
[21:22:10.866][4] Client 13 is going to be disconnected: /usr/libexec/upowerd[1183]

Here are the logs for locked/unlocked gphoto2 --storage-info --debug:

After running the above test, I tried the following:

Unplugged the iphone, plugged back while locked: gphoto2 no longer saw the device
Unplug + Plug back, while locked: gphoto2 stalled
Unlocked the iphone, was asked to pair with the computer
Paired: gphoto2 was fast again
Unplugged, plugged back while unlocked: gphoto2 was fast
Lock while plugged: gphoto2 was slow again
Unlocked while plugged: gphoto2 was fast
Locked while plugged: gphoto2 was slow again

In the last few lock/unlock cycles, gphoto2 would respond instantly if I unlocked the device while it was stalled:

iphone6-unlocked-while-stalled.log

gphoto / libgphoto2

libgphoto2 stalls for 9+ seconds when querying a locked iPhone #480

Current master behavior

With ptp_queue_event

Logs