[Pkg-gtkpod-devel] Bug#942832: usbmuxd freezes when connecting iPhone6 while locked

Tue Oct 22 09:09:45 BST 2019

Package: usbmuxd
Version: 1.1.1~git20181007.f838cf6-1+b1
Severity: important

It seems that usbmuxd is freezing my whole system when I plug a locked
iPhone 6.

I'm attaching a log of journalctl -f and usbmuxd -f, both with the
iPhone locked and then unlocked.

I wasn't able to find any similar bug upstream but I see that usbmuxd is
a snapshot from 2018 while libusbmuxd is from 2019.

Perhaps, in the usual ABI break charm of libimobiledevice and friends,
this needs a bump and rebuild. On a quick test with dpkg-buildpackage
-us -uc of usbmuxd-1.1.1~git20181007.f838cf6, it seems to work "fine"
with the rebuild.

Note that I'm also running a rebuilt libimobiledevice6 because of
https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=941703

Attaching the log. Happy to help debug.

-- System Information:
Debian Release: bullseye/sid
  APT prefers unstable-debug
  APT policy: (500, 'unstable-debug'), (500, 'unstable')
Architecture: amd64 (x86_64)

Kernel: Linux 5.2.0-3-amd64 (SMP w/4 CPU cores)
Kernel taint flags: TAINT_PROPRIETARY_MODULE, TAINT_WARN, TAINT_OOT_MODULE, TAINT_UNSIGNED_MODULE
Locale: LANG=en_US.UTF-8, LC_CTYPE=en_US.UTF-8 (charmap=UTF-8), LANGUAGE=en_US:en (charmap=UTF-8)
Shell: /bin/sh linked to /usr/bin/dash
Init: systemd (via /run/systemd/system)
LSM: AppArmor: enabled

Versions of packages usbmuxd depends on:
ii  adduser            3.118
ii  libc6              2.29-2
ii  libimobiledevice6  1.2.1~git20181030.92c5462-1
ii  libplist3          2.0.1~git20190104.3f96731-1
ii  libusb-1.0-0       2:1.0.23-1

usbmuxd recommends no packages.

usbmuxd suggests no packages.

-- no debconf information
-------------- next part --------------
/*************************************
/************************************* Connecting iPhone 6 locked
/*************************************

[02:46:59]libertad:debian$ journalctl -f

-- Logs begin at Fri 2019-10-04 16:08:34 -05. --
oct 22 02:42:17 libertad systemd[1]: packagekit.service: Succeeded.
oct 22 02:42:23 libertad NetworkManager[726]: <info>  [1571730143.8598] dhcp4 (wlx503eaaec81c0): state changed bound -> bound
oct 22 02:42:23 libertad dbus-daemon[691]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' requested by ':1.10' (uid=0 pid=726 comm="/usr/sbin/NetworkManager --no-daemon")
oct 22 02:42:23 libertad systemd[1]: Starting Network Manager Script Dispatcher Service...
oct 22 02:42:23 libertad dbus-daemon[691]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
oct 22 02:42:23 libertad systemd[1]: Started Network Manager Script Dispatcher Service.
oct 22 02:42:34 libertad systemd[1]: NetworkManager-dispatcher.service: Succeeded.
oct 22 02:46:53 libertad sudo[2807]:   diegoe : TTY=pts/0 ; PWD=/home/diegoe/debian ; USER=root ; COMMAND=/usr/bin/apt install usbmuxd
oct 22 02:46:53 libertad sudo[2807]: pam_unix(sudo:session): session opened for user root by (uid=0)
oct 22 02:46:53 libertad sudo[2807]: pam_unix(sudo:session): session closed for user root
oct 22 02:47:06 libertad sudo[2822]:   diegoe : TTY=pts/0 ; PWD=/home/diegoe/debian ; USER=root ; COMMAND=/usr/sbin/usbmuxd --user usbmux --systemd -f -v
oct 22 02:47:06 libertad sudo[2822]: pam_unix(sudo:session): session opened for user root by (uid=0)
oct 22 02:47:15 libertad kernel: usb 1-2.1: new high-speed USB device number 34 using xhci_hcd
oct 22 02:47:15 libertad kernel: usb 1-2.1: New USB device found, idVendor=05ac, idProduct=12a8, bcdDevice= 7.02
oct 22 02:47:15 libertad kernel: usb 1-2.1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
oct 22 02:47:15 libertad kernel: usb 1-2.1: Product: iPhone
oct 22 02:47:15 libertad kernel: usb 1-2.1: Manufacturer: Apple Inc.
oct 22 02:47:15 libertad kernel: usb 1-2.1: SerialNumber: 31c7f286debf300e6f6a929b7b72bcea8dd175f1
oct 22 02:47:15 libertad mtp-probe[2827]: checking bus 1, device 34: "/sys/devices/pci0000:00/0000:00:14.0/usb1/1-2/1-2.1"
oct 22 02:47:15 libertad mtp-probe[2827]: bus: 1, device: 34 was not an MTP device
oct 22 02:47:15 libertad kernel: ipheth 1-2.1:4.2: Apple iPhone USB Ethernet device attached
oct 22 02:47:15 libertad NetworkManager[726]: <info>  [1571730435.8924] manager: (eth0): new Ethernet device (/org/freedesktop/NetworkManager/Devices/25)
oct 22 02:47:15 libertad mtp-probe[2836]: checking bus 1, device 34: "/sys/devices/pci0000:00/0000:00:14.0/usb1/1-2/1-2.1"
oct 22 02:47:15 libertad mtp-probe[2836]: bus: 1, device: 34 was not an MTP device
oct 22 02:47:15 libertad colord[1037]: CdMain: failed to emit DeviceAdded: failed to register object: An object is already exported for the interface org.freedesktop.ColorManager.Device at /org/freedesktop/ColorManager/devices/sysfs__null_
oct 22 02:47:15 libertad colord[1037]: CdMain: failed to emit DeviceAdded: failed to register object: An object is already exported for the interface org.freedesktop.ColorManager.Device at /org/freedesktop/ColorManager/devices/sysfs__null_
oct 22 02:47:15 libertad systemd-udevd[2826]: Using default interface naming scheme 'v240'.
oct 22 02:47:15 libertad systemd-udevd[2826]: link_config: autonegotiation is unset or enabled, the speed and duplex are not writable.
oct 22 02:47:15 libertad kernel: ipheth 1-2.1:4.2 enp0s20u2u1c4i2: renamed from eth0
oct 22 02:47:15 libertad NetworkManager[726]: <info>  [1571730435.9803] device (eth0): interface index 22 renamed iface from 'eth0' to 'enp0s20u2u1c4i2'
oct 22 02:47:15 libertad NetworkManager[726]: <info>  [1571730435.9922] device (enp0s20u2u1c4i2): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external')
oct 22 02:47:16 libertad NetworkManager[726]: <info>  [1571730436.9820] device (enp0s20u2u1c4i2): carrier: link connected
oct 22 02:47:16 libertad kernel: IPv6: ADDRCONF(NETDEV_CHANGE): enp0s20u2u1c4i2: link becomes ready
oct 22 02:47:16 libertad NetworkManager[726]: <info>  [1571730436.9845] device (enp0s20u2u1c4i2): state change: unavailable -> disconnected (reason 'carrier-changed', sys-iface-state: 'managed')
oct 22 02:47:18 libertad ModemManager[678]: <info>  Couldn't check support for device '/sys/devices/pci0000:00/0000:00:14.0/usb1/1-2/1-2.1': not supported by any plugin
zzzzzz
oct 22 02:47:58 libertad kernel: usb 1-2.1: USB disconnect, device number 34
oct 22 02:47:58 libertad NetworkManager[726]: <info>  [1571730478.2955] device (enp0s20u2u1c4i2): state change: disconnected -> unmanaged (reason 'removed', sys-iface-state: 'removed')
oct 22 02:47:58 libertad kernel: ipheth 1-2.1:4.2: Apple iPhone USB Ethernet now disconnected
oct 22 02:47:58 libertad sudo[2822]: pam_unix(sudo:session): session closed for user root

[02:46:53]libertad:debian$ sudo /usr/sbin/usbmuxd --user usbmux --systemd -f -v 

[02:47:06.761][3] usbmuxd v1.1.1 starting up
[02:47:06.761][4] Creating socket
[02:47:06.762][3] Successfully dropped privileges to 'usbmux'
[02:47:06.762][4] Initializing USB
[02:47:06.766][4] Registering for libusb hotplug events
[02:47:06.766][4] 0 devices detected
[02:47:06.766][3] Initialization complete
[02:47:06.766][3] Enabled exit on SIGUSR1 if no devices are attached. Start a new instance with "--exit" to trigger.
[02:47:06.766][4] New client on fd 11 (pid 31639)
[02:47:15.881][4] Found new device with v/p 05ac:12a8 at 1-34
[02:47:15.881][3] Could not get old configuration descriptor for device 1-34: -5
[02:47:15.881][4] Setting configuration for device 1-34, from 0 to 4
[02:47:15.891][4] Found interface 1 with endpoints 04/85 for device 1-34
[02:47:15.891][4] Using wMaxPacketSize=512 for device 1-34
[02:47:15.891][4] USB Speed is 480 MBit/s for device 1-34
[02:47:15.891][4] Got lang ID 1033 for device 1-34
[02:47:15.892][4] Got serial '31c7f286debf300e6f6a929b7b72bcea8dd175f1' for device 1-34
[02:47:15.892][3] Connecting to new device on location 0x10022 as ID 1
[02:47:15.892][3] Connected to v2.0 device 1 on location 0x10022 with serial number 31c7f286debf300e6f6a929b7b72bcea8dd175f1
[02:47:15.899][4] preflight_worker_handle_device_add: Starting preflight on device 31c7f286debf300e6f6a929b7b72bcea8dd175f1...
[02:47:15.899][4] New client on fd 14 (self)
[02:47:15.921][4] New client on fd 16 (self)
[02:47:15.921][4] Client 16 connection closed
[02:47:15.921][4] Disconnecting client fd 16
[02:47:15.926][4] New client on fd 16 (self)
[02:47:15.928][4] Client 16 connection closed
[02:47:15.928][4] Disconnecting client fd 16

/*************************************
/************************************* SYSTEM FREEZE
/*************************************

[02:47:15.970][4] preflight_worker_handle_device_add: StartSession success for device 31c7f286debf300e6f6a929b7b72bcea8dd175f1
[02:47:15.970][4] preflight_worker_handle_device_add: Finished preflight on device 31c7f286debf300e6f6a929b7b72bcea8dd175f1
[02:47:15.971][4] New client on fd 15 (pid 31639)
[02:47:15.971][4] Client 15 connection closed
[02:47:15.971][4] Disconnecting client fd 15
[02:47:15.971][4] New client on fd 15 (pid 31639)
[02:47:15.972][4] Disconnecting client fd 14
[02:47:15.975][4] Disconnecting client fd 15
[02:47:21.022][4] New client on fd 13 (pid 929)
[02:47:21.023][4] Client 13 connection closed
[02:47:21.023][4] Disconnecting client fd 13
[02:47:21.023][4] New client on fd 13 (pid 929)
[02:47:21.028][4] New client on fd 14 (pid 929)
[02:47:21.029][4] Client 14 connection closed
[02:47:21.029][4] Disconnecting client fd 14
[02:47:21.029][4] New client on fd 14 (pid 929)
[02:47:21.029][4] Client 14 connection closed
[02:47:21.029][4] Disconnecting client fd 14
[02:47:21.033][4] New client on fd 14 (pid 929)
[02:47:21.034][4] Client 14 connection closed
[02:47:21.034][4] Disconnecting client fd 14
[02:47:21.075][4] Disconnecting client fd 13
/**** control + C ****/
[02:47:58.242][4] Device 1-34 RX aborted due to error or disconnect
[02:47:58.242][4] Device 1-34 RX aborted due to error or disconnect
[02:47:58.242][4] Device 1-34 RX aborted due to error or disconnect
[02:47:58.242][3] Removed device 1 on location 0x10022
[02:47:58.325][4] Caught SIGUSR1, checking if we can terminate (no more devices attached)...
[02:47:58.325][4] Event processing interrupted
[02:47:58.325][3] usbmuxd shutting down
[02:47:58.425][4] Disconnecting client fd 11
[02:47:58.425][3] Shutdown complete

/*************************************
/************************************* Connecting iPhone 6 unlocked
/*************************************

[02:48:30]libertad:debian$ journalctl -f

-- Logs begin at Fri 2019-10-04 16:08:34 -05. --
oct 22 02:48:12 libertad systemd[1088]: Starting Tracker metadata database store and lookup manager...
oct 22 02:48:12 libertad dbus-daemon[31296]: [session uid=1000 pid=31296] Successfully activated service 'org.freedesktop.Tracker1'
oct 22 02:48:12 libertad systemd[1088]: Started Tracker metadata database store and lookup manager.
oct 22 02:48:12 libertad dbus-daemon[691]: [system] Successfully activated service 'org.freedesktop.timedate1'
oct 22 02:48:12 libertad systemd[1]: Started Time & Date Service.
oct 22 02:48:12 libertad dbus-daemon[31296]: [session uid=1000 pid=31296] Successfully activated service 'org.gnome.Calendar'
oct 22 02:48:12 libertad gnome-calendar[2897]: Link of type "section" missing "id=". Merging will not be possible.
oct 22 02:48:12 libertad gnome-shell[31534]: meta_window_set_stack_position_no_sync: assertion 'window->stack_position >= 0' failed
oct 22 02:48:28 libertad sudo[3000]:   diegoe : TTY=pts/0 ; PWD=/home/diegoe/debian ; USER=root ; COMMAND=/usr/sbin/usbmuxd --user usbmux --systemd -f -v
oct 22 02:48:28 libertad sudo[3000]: pam_unix(sudo:session): session opened for user root by (uid=0)
oct 22 02:48:38 libertad kernel: usb 1-2.1: new high-speed USB device number 35 using xhci_hcd
oct 22 02:48:38 libertad kernel: usb 1-2.1: New USB device found, idVendor=05ac, idProduct=12a8, bcdDevice= 7.02
oct 22 02:48:38 libertad kernel: usb 1-2.1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
oct 22 02:48:38 libertad kernel: usb 1-2.1: Product: iPhone
oct 22 02:48:38 libertad kernel: usb 1-2.1: Manufacturer: Apple Inc.
oct 22 02:48:38 libertad kernel: usb 1-2.1: SerialNumber: 31c7f286debf300e6f6a929b7b72bcea8dd175f1
oct 22 02:48:38 libertad mtp-probe[3009]: checking bus 1, device 35: "/sys/devices/pci0000:00/0000:00:14.0/usb1/1-2/1-2.1"
oct 22 02:48:38 libertad mtp-probe[3009]: bus: 1, device: 35 was not an MTP device
oct 22 02:48:38 libertad kernel: ipheth 1-2.1:4.2: Apple iPhone USB Ethernet device attached
oct 22 02:48:38 libertad NetworkManager[726]: <info>  [1571730518.5825] manager: (eth0): new Ethernet device (/org/freedesktop/NetworkManager/Devices/26)
oct 22 02:48:38 libertad mtp-probe[3017]: checking bus 1, device 35: "/sys/devices/pci0000:00/0000:00:14.0/usb1/1-2/1-2.1"
oct 22 02:48:38 libertad mtp-probe[3017]: bus: 1, device: 35 was not an MTP device
oct 22 02:48:38 libertad colord[1037]: CdMain: failed to emit DeviceAdded: failed to register object: An object is already exported for the interface org.freedesktop.ColorManager.Device at /org/freedesktop/ColorManager/devices/sysfs__null_
oct 22 02:48:38 libertad colord[1037]: CdMain: failed to emit DeviceAdded: failed to register object: An object is already exported for the interface org.freedesktop.ColorManager.Device at /org/freedesktop/ColorManager/devices/sysfs__null_
oct 22 02:48:38 libertad systemd-udevd[3023]: Using default interface naming scheme 'v240'.
oct 22 02:48:38 libertad systemd-udevd[3023]: link_config: autonegotiation is unset or enabled, the speed and duplex are not writable.
oct 22 02:48:38 libertad kernel: ipheth 1-2.1:4.2 enp0s20u2u1c4i2: renamed from eth0
oct 22 02:48:38 libertad NetworkManager[726]: <info>  [1571730518.6922] device (eth0): interface index 23 renamed iface from 'eth0' to 'enp0s20u2u1c4i2'
oct 22 02:48:38 libertad NetworkManager[726]: <info>  [1571730518.7044] device (enp0s20u2u1c4i2): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external')
oct 22 02:48:38 libertad systemd-udevd[3008]: Using default interface naming scheme 'v240'.
oct 22 02:48:40 libertad NetworkManager[726]: <info>  [1571730520.0223] device (enp0s20u2u1c4i2): carrier: link connected
oct 22 02:48:40 libertad kernel: IPv6: ADDRCONF(NETDEV_CHANGE): enp0s20u2u1c4i2: link becomes ready
oct 22 02:48:40 libertad NetworkManager[726]: <info>  [1571730520.0241] device (enp0s20u2u1c4i2): state change: unavailable -> disconnected (reason 'carrier-changed', sys-iface-state: 'managed')
oct 22 02:48:41 libertad ModemManager[678]: <info>  Couldn't check support for device '/sys/devices/pci0000:00/0000:00:14.0/usb1/1-2/1-2.1': not supported by any plugin
oct 22 02:48:42 libertad systemd[1]: systemd-timedated.service: Succeeded.
oct 22 02:48:42 libertad tracker-store[2967]: OK
oct 22 02:48:42 libertad systemd[1088]: tracker-store.service: Succeeded.

[02:48:19]libertad:debian$ sudo /usr/sbin/usbmuxd --user usbmux --systemd -f -v 

[02:48:28.204][3] usbmuxd v1.1.1 starting up
[02:48:28.204][4] Creating socket
[02:48:28.205][3] Successfully dropped privileges to 'usbmux'
[02:48:28.205][4] Initializing USB
[02:48:28.209][4] Registering for libusb hotplug events
[02:48:28.209][4] 0 devices detected
[02:48:28.209][3] Initialization complete
[02:48:28.209][3] Enabled exit on SIGUSR1 if no devices are attached. Start a new instance with "--exit" to trigger.
[02:48:28.209][4] New client on fd 11 (pid 31639)
[02:48:38.574][4] Found new device with v/p 05ac:12a8 at 1-35
[02:48:38.574][3] Could not get old configuration descriptor for device 1-35: -5
[02:48:38.574][4] Setting configuration for device 1-35, from 0 to 4
[02:48:38.581][4] Found interface 1 with endpoints 04/85 for device 1-35
[02:48:38.581][4] Using wMaxPacketSize=512 for device 1-35
[02:48:38.581][4] USB Speed is 480 MBit/s for device 1-35
[02:48:38.584][4] Got lang ID 1033 for device 1-35
[02:48:38.586][4] Got serial '31c7f286debf300e6f6a929b7b72bcea8dd175f1' for device 1-35
[02:48:38.586][3] Connecting to new device on location 0x10023 as ID 1
[02:48:38.586][3] Connected to v2.0 device 1 on location 0x10023 with serial number 31c7f286debf300e6f6a929b7b72bcea8dd175f1
[02:48:38.587][4] preflight_worker_handle_device_add: Starting preflight on device 31c7f286debf300e6f6a929b7b72bcea8dd175f1...
[02:48:38.587][4] New client on fd 14 (self)
[02:48:38.608][4] New client on fd 16 (self)
[02:48:38.608][4] Client 16 connection closed
[02:48:38.608][4] Disconnecting client fd 16
[02:48:38.615][4] New client on fd 16 (self)
[02:48:38.617][4] Client 16 connection closed
[02:48:38.617][4] Disconnecting client fd 16
[02:48:38.695][4] preflight_worker_handle_device_add: StartSession success for device 31c7f286debf300e6f6a929b7b72bcea8dd175f1
[02:48:38.695][4] preflight_worker_handle_device_add: Finished preflight on device 31c7f286debf300e6f6a929b7b72bcea8dd175f1
[02:48:38.696][4] New client on fd 15 (pid 31639)
[02:48:38.696][4] New client on fd 16 (pid 31639)
[02:48:38.696][4] Client 15 connection closed
[02:48:38.696][4] Disconnecting client fd 15
[02:48:38.771][4] Disconnecting client fd 16
[02:48:38.855][4] Disconnecting client fd 14
[02:48:44.020][4] New client on fd 13 (pid 929)
[02:48:44.021][4] Client 13 connection closed
[02:48:44.021][4] Disconnecting client fd 13
[02:48:44.021][4] New client on fd 13 (pid 929)
[02:48:44.027][4] New client on fd 14 (pid 929)
[02:48:44.028][4] Client 14 connection closed
[02:48:44.028][4] Disconnecting client fd 14
[02:48:44.028][4] New client on fd 14 (pid 929)
[02:48:44.029][4] Client 14 connection closed
[02:48:44.029][4] Disconnecting client fd 14
[02:48:44.037][4] New client on fd 14 (pid 929)
[02:48:44.037][4] Client 14 connection closed
[02:48:44.037][4] Disconnecting client fd 14
[02:48:44.116][4] Disconnecting client fd 13

/**** control + C ****/

[02:48:55.594][3] Caught signal 2, exiting
[02:48:55.594][4] Event processing interrupted
[02:48:55.594][3] usbmuxd shutting down
[02:48:55.694][3] Removed device 1 on location 0x10023
[02:48:55.695][4] Disconnecting client fd 11
[02:48:55.695][3] Shutdown complete