New devices not discovered by udev add on Linux

[libimobiledevice]

New devices not discovered by udev add on Linux

[greg-dennis]

There may also be some undesirable interaction between the usbmuxd rules file and the libgpod rules file that may or may not be related. It looked like the presence of libgpod rules could cause the usbmuxd fd polling to go into an infinite fd polling loop. I don't understand the problem well enough to file a separate bug about though.

[FunkyM]

Please try to increase the focus of your description on the actual problem.
Please also define "Linux" and udev more precisely by providing libusb stack, kernel, distro and a copy of the udev rules.

[greg-dennis]

Sure, I'll try to provide more details.

Linux kernel and distro: 3.13.0-30-generic #54~precise2-Ubuntu SMP Wed Jun 11 16:11:17 UTC 2014 x86_64 x86_64 x86_64 GNU/Linux

The udev rules are the same 39-usbmuxd.rules provided in the usbmuxd project where @Prefix@ is /usr/local.

There is no libusb stack trace, because no error occurs. The return value of libusb_get_device_list when triggered by the udev rule on device add simply does not include the new device.

Anything else that would be helpful?

[FunkyM]

Does the device appear in the "lsusb" output?

[greg-dennis]

Yes, it does. I suspect usb_discover may be called just before it appears, though. The "Device discovery triggered by udev" log line, but I think usb_discover is just called too soon. Maybe it's new behavior is newer versions of libusb? We're using libusbm 1.0.18, which is post-hotplug support, for what it's worth.

[nikias]

Really strange behavior. What happens if you add a sleep(5); right after this line: https://github.com/libimobiledevice/usbmuxd/blob/master/src/main.c#L484
This will hold off 5 seconds before signaling the already running instance to check for new devices.

[FunkyM]

Please verify with usbmuxd 1.0.9 as it includes fixes for exactly these issues.

[greg-dennis]

Hmm, the issue persists in usbmuxd 1.0.9, and adding that sleep(5) has no effect. I am not using systemd. I have to rerun usbmuxd at the command line to get the device to be discovered. Anything else I could try?

[greg-dennis]

To debug, I'm start from a clean state with no usbmuxd running and no devices attached. Now I run:
$ sudo /usr/local/sbin/usbmuxd -u -U usbmux -v -f

This produces the following output:
[16:24:38.477][3] usbmuxd v1.0.9 starting up
[16:24:38.477][4] Creating socket
[16:24:38.542][3] Successfully dropped privileges to 'usbmux'
[16:24:38.542][4] Initializing USB
[16:24:38.545][4] 0 devices detected
[16:24:38.545][3] Initialization complete
[16:24:38.545][4] New client on fd 13
[16:24:38.546][4] New client on fd 14

Now when I attach the device, I see usbmuxd enter a suspicious cycle:
[16:25:29.148][4] New client on fd 15
[16:25:29.248][4] Client 15 connection closed
[16:25:29.248][4] Disconnecting client fd 15
[16:25:29.148][4] New client on fd 15
[16:25:29.248][4] Client 15 connection closed
[16:25:29.248][4] Disconnecting client fd 15
( this sequence repeats about 8 times)
[16:25:34.161][4] Caught SIGUSR2, scheduling device discovery
[16:25:34.161][4] Device discovery triggered by udev
[16:25:29.148][4] New client on fd 15
[16:25:29.248][4] Client 15 connection closed
[16:25:29.248][4] Disconnecting client fd 15
[16:25:29.148][4] New client on fd 15
[16:25:29.248][4] Client 15 connection closed
[16:25:29.248][4] Disconnecting client fd 15
(this sequence repeats for about another 13 times)

The device is not picked up by idevice_id -l.

Now, with the device still attached and the original usbmuxd still running, in a separate terminal, I repeat the usbmuxd command from before:
$ sudo /usr/local/sbin/usbmuxd -u -U usbmux -v -f
This second command produces the expected output:
[16:28:20.587][3] usbmuxd v1.0.9 starting up
[16:28:20.587][3] Another instance is already running (pid 27142). Telling it to check for devices.
[16:28:20.587][3] Sending signal SIGUSR2 to instance with pid 27142

And the first commands output now continues with:
[16:28:25.587][4] Caught SIGUSR2, scheduling device discovery
[16:28:25.587][4] Device discovery triggered by udev
[16:28:25.587][4] Found new device with v/p 05ac:12a0 at 1-24

and it continues from there, looking healthy, and the device is picked up by idevice_id -l.

[FunkyM]

Your commandline is? Maybe
usbmuxd -v --user usbmux --udev --foreground works?
Does running like this work?
usbmuxd -v --user usbmux --foreground

[FunkyM]

Well, from your description, it kind of looks like what we expect from usbmuxd in udev mode.
Please post the udev rule file used by your system.

[greg-dennis]

When the device is added, it is not automatically picked up by usbmuxd through the udev rules. That is not expected, right? There looks to be some timing issue between when usbmuxd attempts to discover new devices and when the device is actually ready to be discovered. Here is my 39-usbmuxd.rules file, as generated by configure/make:

# usbmuxd (Apple Mobile Device Muxer listening on /var/run/usbmuxd)

# Initialize iOS devices into "deactivated" USB configuration state and activate usbmuxd
ACTION=="add", SUBSYSTEM=="usb", ATTR{idVendor}=="05ac", ATTR{idProduct}=="12[9a][0-9a-f]", ENV{USBMUX_SUPPORTED}="1", ATTR{bConfigurationValue}="0", OWNER="usbmux", RUN+="/usr/local/sbin/usbmuxd -u -U usbmux"

# Exit usbmuxd when the last device is removed
ACTION=="remove", SUBSYSTEM=="usb", ENV{PRODUCT}=="5ac/12[9a][0-9a-f]/*", ENV{INTERFACE}=="255/*", RUN+="/usr/local/sbin/usbmuxd -x"

[FunkyM]

It works like this. The "add" rule starts a new instance of usbmuxd. If an instance was already running, it signals using SIGUSR2 that the running instance should check for new devices and exits.
This apparently happens:

[16:25:34.161][4] Caught SIGUSR2, scheduling device discovery
[16:25:34.161][4] Device discovery triggered by udev

However it does not seem to actually find any device in your example in the following lines.
Sidenote, you are not using the latest usbmuxd version as that string from above is now "Device discovery triggered" (not that it could change the observed behavior but it might be better to run the latest code).

If the "remove" rule is called and an instance is running, it signals using SIGUSR1 that the running instance should exit if no more devices are attached and exits itself.

Interesting is that once you trigger the "device discovery" by running the command manually, it picks up the new device just fine.

Thus we should check why your device is not discovered when the udev rule is called the second time.

Perhaps it would be interesting if you monitor/log in parallel what udev does:
udevadm monitor --kernel --udev

You can also run usbmuxd in the background mode and verify your kernel output and usbmuxd output matches on a linear timeline.

Please also test increasing verbosity to "-vvv" and look for the line "usb_discover: scanning %d devices".

What distribution is this btw.?

[greg-dennis]

Martin, my usbmuxd version was updated a couple weeks ago, but it looks to be just before the device discovery string was updated. I'm updating now, but before I post any results, could you confirm whether the 'd' from the end of usbmuxd was intentionally truncated in this change:
http://cgit.sukimashita.com/usbmuxd.git/commit/?id=1dc5437d7c25df26368dcce8db75785eb48ec6aa

[greg-dennis]

Assuming that lopping off that d from rules file is a mistake, then after upgrading to head usbmuxd and running with with the long command line options and finest grained logging, I get the same result, only more verbose. I also captured the udevadm output this time. Details:

Output from initial sudo /usr/local/sbin/usbmuxd --user usbmux --udev --foreground -vvv with no devices attached:

[14:15:51.408][3] usbmuxd v1.1.0 starting up
[14:15:51.408][4] Creating socket
[14:15:51.408][5] initialized config_dir to /var/lib/lockdown
[14:15:51.474][3] Successfully dropped privileges to 'usbmux'
[14:15:51.474][5] client_init
[14:15:51.474][5] device_init
[14:15:51.474][4] Initializing USB
[14:15:51.474][5] usb_init for linux / libusb 1.0
[14:15:51.477][6] usb_discover: scanning 12 devices
[14:15:51.477][4] 0 devices detected
[14:15:51.477][3] Initialization complete
[14:15:51.477][3] Automatic device discovery on hotplug disabled.
[14:15:51.477][5] usb polling enable: 0
[14:15:51.477][3] Enabled exit on SIGUSR1 if no devices are attached. Start a new instance with "--exit" to trigger.
[14:15:51.477][4] New client on fd 13
[14:15:51.478][4] New client on fd 14
[14:15:51.478][5] Client command in fd 13 len 16 ver 0 msg 3 tag 93
[14:15:51.478][5] send_pkt fd 13 tag 93 msg 1 payload_length 4
[14:15:51.478][5] Client 13 now LISTENING
[14:15:51.478][5] Client command in fd 14 len 16 ver 0 msg 3 tag 93
[14:15:51.478][5] send_pkt fd 14 tag 93 msg 1 payload_length 4
[14:15:51.478][5] Client 14 now LISTENING
[14:16:02.124][4] New client on fd 15
[14:16:02.124][5] Client command in fd 15 len 504 ver 1 msg 8 tag 1
[14:16:02.125][5] send_pkt fd 15 tag 1 msg 8 payload_length 230
[14:16:02.125][4] Client 15 connection closed
[14:16:02.125][4] Disconnecting client fd 15

Output from udevadm monitor --kernel --udev after connecting an iOS device:

KERNEL[622397.697061] add      /devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.3 (usb)
KERNEL[622397.697895] add      /devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.3/1-1.3:1.0 (usb)
KERNEL[622397.721925] remove   /devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.3/1-1.3:1.0 (usb)
UDEV  [622397.746833] add      /devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.3 (usb)
UDEV  [622397.747771] add      /devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.3/1-1.3:1.0 (usb)
UDEV  [622397.748303] remove   /devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.3/1-1.3:1.0 (usb)

Additional output from the main usbmuxd process when connecting that device:

[14:16:29.624][4] New client on fd 15
[14:16:29.624][5] Client command in fd 15 len 16 ver 0 msg 3 tag 1
[14:16:29.624][5] send_pkt fd 15 tag 1 msg 1 payload_length 4
[14:16:29.624][5] Client 15 now LISTENING
[14:16:29.639][4] Caught SIGUSR2, scheduling device discovery
[14:16:29.639][4] Device discovery triggered
[14:16:29.639][6] usb_discover: scanning 12 devices
[14:16:29.640][4] New client on fd 16
[14:16:29.640][5] Client command in fd 16 len 16 ver 0 msg 3 tag 9
[14:16:29.640][5] send_pkt fd 16 tag 9 msg 1 payload_length 4
[14:16:29.640][5] Client 16 now LISTENING
[14:16:29.724][4] Client 15 connection closed
[14:16:29.724][4] Disconnecting client fd 15
[14:16:29.741][4] Client 16 connection closed
[14:16:29.741][4] Disconnecting client fd 16
[14:16:30.225][4] New client on fd 15
[14:16:30.225][5] Client command in fd 15 len 16 ver 0 msg 3 tag 2
[14:16:30.225][5] send_pkt fd 15 tag 2 msg 1 payload_length 4
[14:16:30.225][5] Client 15 now LISTENING
[14:16:30.325][4] Client 15 connection closed
[14:16:30.325][4] Disconnecting client fd 15
[14:16:30.825][4] New client on fd 15
[14:16:30.825][5] Client command in fd 15 len 16 ver 0 msg 3 tag 3
[14:16:30.825][5] send_pkt fd 15 tag 3 msg 1 payload_length 4
[14:16:30.825][5] Client 15 now LISTENING
[14:16:30.926][4] Client 15 connection closed
[14:16:30.926][4] Disconnecting client fd 15
(this sequence of the last 6 log lines continues about 8 times, with increasing tag numbers on the send_pkt line)

idevice_id -l still shows no devices at this point. Now if I manually run a new usbmuxd process in a new terminal (again, sudo usbmuxd --user usbmux --udev --foreground -vvv) while the initial stays running, it outputs:

[14:17:44.386][4] Caught SIGUSR2, scheduling device discovery
[14:17:44.386][4] Device discovery triggered
[14:17:44.386][6] usb_discover: scanning 13 devices
[14:17:44.386][4] Found new device with v/p 05ac:12a0 at 1-29
[14:17:44.386][3] Could not get old configuration descriptor for device 1-29: -5
[14:17:44.386][4] Setting configuration for device 1-29, from 0 to 4
[14:17:44.610][4] Found interface 1 with endpoints 04/85 for device 1-29
[14:17:44.610][4] Using wMaxPacketSize=512 for device 1-29
[14:17:44.610][3] Connecting to new device on location 0x1001d as ID 1
[14:17:44.610][6] send_packet(1, 0x0, 0x7fff3ad9a9c0, (nil), 0)
[14:17:44.610][5] All 3 RX loops started successfully
[14:17:44.611][6] TX callback dev 1-29 len 20 -> 20 status 0
[14:17:44.611][6] RX callback dev 1-29 len 20 status 0
[14:17:44.611][6] Mux data input for device 0x7f5734a5eb20: 0x7f5734a89020 len 20
[14:17:44.611][6] send_packet(1, 0x2, (nil), 0x9e7d11, 1)
[14:17:44.611][3] Connected to v2.0 device 1 on location 0x1001d with serial number f53f8c604097ca09526eadb1685b241cc0954948
[14:17:44.611][6] TX callback dev 1-29 len 17 -> 17 status 0
[14:17:44.611][4] preflight_worker_handle_device_add: Starting preflight on device f53f8c604097ca09526eadb1685b241cc0954948...
[14:17:44.611][4] New client on fd 17
[14:17:44.612][5] Client command in fd 17 len 592 ver 1 msg 8 tag 1
(lots more output here that I could send you if you're really interested)

Now the device is picked up by idevice_id.

[FunkyM]

Yes, 1dc5437 is a bug. Fixed in git master.
Other than that thanks for the details, this brings us closer to the issue.
It can be seen now that usbmuxd appears to interact correctly with udev, but the device is not visible to libusb yet (only 12 devices):

[14:16:29.639][4] Caught SIGUSR2, scheduling device discovery
[14:16:29.639][4] Device discovery triggered
[14:16:29.639][6] usb_discover: scanning 12 devices

When you trigger the device discovery a bit later you can see (13 devices):

[14:17:44.386][4] Caught SIGUSR2, scheduling device discovery
[14:17:44.386][4] Device discovery triggered
[14:17:44.386][6] usb_discover: scanning 13 devices
[14:17:44.386][4] Found new device with v/p 05ac:12a0 at 1-29

This means that the device we are looking after is not "visible" to usb_discover() when udev has triggered an "add" event and thus device discovery.

You mentioned something about libusbm? Which libusb are you using now?

[greg-dennis]

Ok, I have a workaround/fix. On line 206, right before the usb_discover call, I insert sleep(5):
http://cgit.sukimashita.com/usbmuxd.git/tree/src/main.c?id=1dc5437d7c25df26368dcce8db75785eb48ec6aa#n206

This delays usb_discover until after the new client is detected, and everything works. This doesn't feel like the "proper" fix, but it works for now.

My distribution: Ubuntu 14.04 LTS (Trusty)

[greg-dennis]

I meant to write "libusb" not "libusbm" above. We are using libusb 1.0.18.

[greg-dennis]

FYI: even a sleep(1) appears to be sufficient.

[FunkyM]

Thank you. It is evident that we have a timing issue between udev/libusb here that should not exist.
Please try to change the udev rule item from ATTR{bConfigurationValue}="0" to ATTR{bConfigurationValue}="4" and let me know if it improves/changes the detection.
Running sudo udevadm control --reload-rules should make udev aware of changes.

[greg-dennis]

Unfortunately, using ATTR{bConfigurationValue}="4" does not obviate the need for the sleep.

[greg-dennis]

@IOSH4CK your issue doesn't bear any resemblance to this bug. Please file a separate issue.

[FunkyM]

@progressnerd Do you still have the file /lib/udev/rules.d/85-usbmuxd.rules? How did you install libusb 1.0.18, afaik Ubuntu 14.04 only has libusb 1.0.17?

[greg-dennis]

I do not have the /lib/udev/rules.d/85-usbmuxd.rules file. We build static binaries hermetically from our code repository, and our repo has libusb 1.0.18. I could see if the problem reproduces with another specific libusb version, if you'd like me to try that.

[greg-dennis]

@IOSH4CK Please stop trying to hijack this thread. Create your own issue.

[FunkyM]

Ok, finally reproduced it in testing.
It looks like this can be tagged with "Ubuntu" and I assume it doesn't have to do with libusb but rather with the udev/upstart mess.

[fulminemizzega]

From what I've read here, and testing the output of usbmuxd and udevadm, I also I'm experiencing the same issue with Gentoo. I think the udev rules are the same, from the gui side what happens is that I plug a device, udev start usbmuxd, something happens with gnome as it shows for a second the mounted device notication, then usbmuxd process quits. Nautilus still shows the device mounted, as soon as you try to access it nautilus crashes or throws an error. On the command line everything looks like what you've written here, running manually usbmuxd -v -u -U usbmux after works right.
usbmuxd 1.0.8, libusb 1.0.19

[FunkyM]

A note for later investigation, Gentoo uses the OpenRC init system.

[fulminemizzega]

I'm using systemd (required by gnome 3). On gentoo the usbmuxd package does not install any .service files.

[kg4ysy]

I'm on Gentoo using OpenRC. In order to get usbmuxd to start when connecting an iPhone and die when the last device is unplugged, I edited /lib/udev/rules.d/39-usbmuxd.rules. I am using usbmuxd 1.1.0 which was provided from portage.

I added RUN+="/usr/sbin/usbmuxd" to the add action. I also changed the -x to -X to force usbmuxd to die for the remove action.