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
/************************************* /************************************* 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
