It seems that after new device is inserted, running gpg-card l or (gpg --card-status), detecting new device is unstable.
IIUC, it may be the bug of libusb.
Description
Description
Event Timeline
Comment Actions
In libusb (1.0.26), I found this:
diff --git a/libusb/os/linux_udev.c b/libusb/os/linux_udev.c index 9ec9eb17..66e27244 100644 --- a/libusb/os/linux_udev.c +++ b/libusb/os/linux_udev.c @@ -194,9 +194,11 @@ static void *linux_udev_event_thread_main(void *arg) } if (fds[1].revents) { usbi_mutex_static_lock(&linux_hotplug_lock); - udev_dev = udev_monitor_receive_device(udev_monitor); - if (udev_dev) - udev_hotplug_event(udev_dev); + do { + udev_dev = udev_monitor_receive_device(udev_monitor); + if (udev_dev) + udev_hotplug_event(udev_dev); + } while (udev_dev); usbi_mutex_static_unlock(&linux_hotplug_lock); } }
Perhaps, this can improve the situation.
Comment Actions
What I learned today:
- libusb backend for Linux does:
- scanning devices, it uses hotplug feature
- hotplug feature uses udev_monitor_new_from_netlink and udev_monitor_receive_device, which are available in libudev (it communicates udev through AF_NETLINK socket)
- libudev differs in Devuan
- Distributions with systemd, libudev nowadays includes static-libsystemd
- In Devuan, it is included in eudev : https://git.devuan.org/devuan/eudev
- At initialization, hotplug feature spawns linux_udev_event_thread_main (its name is {libusb_event})
- It is this thread, which receives information of device insertion/removal
Comment Actions
The interesting thing is that I did not changed my box but it "suddenly" started to misbehave. Thus I conclude this is a matter of our own changes. The log I sent you by PM was done with my suggested improvement (npth_unlock/lock around libusb_get-device_list) and it might actually helped a bit - I am not sure. I will test again w/o that change. Or maybe I should bisect.
Comment Actions
Okay, the mentioned patch does not help. I now tried the actual use
case of mine, which is to ssh without the token plugged in. I clicked
two times OK, then inserted the token and then I had to click
around dozen times onto OK before the inserted card was detected.
Here is the last check resulting in "no such device" commencing at
15:23:49 - the device was inserted 41 seconds earlier.
DBG: chan_7 <- SERIALNO --all
DBG: libusb{4}: [43.658888] [00001c84] libusb: debug [libusb_get_device_list]
DBG: libusb{4}: [43.658931] [00001c84] libusb: debug [libusb_get_device_descriptor]
DBG: libusb{4}: [43.659005] [00001c84] libusb: debug [libusb_get_device_descriptor]
DBG: libusb{4}: [43.659058] [00001c84] libusb: debug [libusb_get_device_descriptor]
DBG: libusb{4}: [43.659118] [00001c84] libusb: debug [libusb_get_device_descriptor]
DBG: libusb{4}: [43.659175] [00001c84] libusb: debug [libusb_get_device_descriptor]
DBG: chan_7 -> ERR 100696144 No such device <SCD>Then udev kicked this:
DBG: libusb{4}: [44.593546] [00001c86] libusb: debug [linux_get_device_address] getting address for device: 2-1.1 detached: 0
DBG: libusb{4}: [44.593581] [00001c86] libusb: debug [linux_get_device_address] scan 2-1.1
DBG: libusb{4}: [44.593647] [00001c86] libusb: debug [linux_get_device_address] bus=2 dev=37
DBG: libusb{4}: [44.593661] [00001c86] libusb: debug [udev_hotplug_event] udev hotplug event. action: add.
DBG: libusb{4}: [44.593672] [00001c86] libusb: debug [linux_enumerate_device] busnum 2 devaddr 37 session_id 549
DBG: libusb{4}: [44.593684] [00001c86] libusb: debug [linux_enumerate_device] allocating new device for 2/37 (session 549)
DBG: libusb{4}: [44.593734] [00001c86] libusb: debug [linux_get_parent_info] dev 0x7fef04002340 (2-1.1) has parent 0x7fef0c00b870 (2-1) port 1Here I hit the OK button again:
DBG: chan_7 <- SERIALNO --all
DBG: libusb{4}: [44.820358] [00001c84] libusb: debug [libusb_get_device_list]
DBG: libusb{4}: [44.820384] [00001c84] libusb: debug [libusb_get_device_descriptor]
DBG: libusb{4}: [44.820446] [00001c84] libusb: debug [libusb_get_device_descriptor]
DBG: libusb{4}: [44.820496] [00001c84] libusb: debug [libusb_get_device_descriptor]
DBG: libusb{4}: [44.820540] [00001c84] libusb: debug [libusb_get_device_descriptor]
DBG: libusb{4}: [44.820571] [00001c84] libusb: debug [libusb_get_device_descriptor]
DBG: libusb{4}: [44.820597] [00001c84] libusb: debug [libusb_get_device_descriptor]
DBG: libusb{4}: [44.820630] [00001c84] libusb: debug [libusb_open] open 2.37
DBG: libusb{4}: [44.820664] [00001c84] libusb: debug [usbi_add_event_source] add fd 13 events 4
[...]Things worked from here on. The question is why we have this delay.
Comment Actions
I went back to 2.3.3 and it seems it never worked as I expected. But we should understand the reason for the long delay.
Comment Actions
I wrote a simple testusb.c if monitoring USB devices works:
#include <stdlib.h>
#include <libusb.h>
#include <poll.h>
#include <stdio.h>
static void
log_usb (libusb_context *ctx, enum libusb_log_level level, const char *str)
{
fputs (str, stderr);
}
int
main (int argc, const char *argv[])
{
int r;
libusb_set_option (NULL, LIBUSB_OPTION_LOG_LEVEL, LIBUSB_LOG_LEVEL_DEBUG);
libusb_set_log_cb (NULL, log_usb, LIBUSB_LOG_CB_GLOBAL);
r = libusb_init (NULL);
if (r)
exit (1);
poll (NULL, 0, -1);
return 0;
}
/* Local Variables: */
/* compile-command: "cc -o testusb testusb.c -I /usr/include/libusb-1.0 -lusb-1.0" */
/* End: */Running ./testusb, we can see what's going on in an application with libusb.
In my environment, it detects removal soon. It takes a bit of time (like a second or so) for detecting new device, but it works.
I think that testing with testusb, we may see if it's libusb issue or not.