USB autosuspend problem: libusb_open returns LIBUSB_ERROR_IO

[rodarima]

Hello,
I have a C3PO LTC31 SmartCard Reader (0783:0003) which seems to work "fine" after the first error at libusb_open:

# /usr/bin/pcscd --debug --foreground --auto-exit
...
00000021 ccid_usb.c:302:OpenUSBByName() Using: /usr/lib/pcsc/drivers/ifd-ccid.bundle/Contents/Info.plist
00001069 ccid_usb.c:320:OpenUSBByName() ifdManufacturerString: Ludovic Rousseau (ludovic.rousseau@free.fr)
00000018 ccid_usb.c:321:OpenUSBByName() ifdProductString: Generic CCID driver
00000007 ccid_usb.c:322:OpenUSBByName() Copyright: This driver is protected by terms of the GNU Lesser General Public License version 2.1, or (at your option) any later version.
00641431 ccid_usb.c:560:OpenUSBByName() Can't libusb_open(1/56): LIBUSB_ERROR_IO
00000045 ccid_usb.c:189:close_libusb_if_needed() libusb_exit
00003914 ccid_usb.c:789:OpenUSBByName() Device not found?
00000033 ifdhandler.c:151:CreateChannelByNameOrChannel() failed
00000014 readerfactory.c:1105:RFInitializeReader() Open Port 0x200000 Failed (usb:0783/0003:libudev:0:/dev/bus/usb/001/056)
00000007 readerfactory.c:376:RFAddReader() C3PO LTC3x USB (00004390) init failed.
00000015 readerfactory.c:609:RFRemoveReader() UnrefReader() count was: 1
00000007 readerfactory.c:1125:RFUnInitializeReader() Attempting shutdown of C3PO LTC3x USB (00004390) 00 00.
00000006 readerfactory.c:986:RFUnloadReader() Unloading reader driver.
00000459 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x0451, PID: 0x8042, path: /dev/bus/usb/001/003
00000195 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x045E, PID: 0x078C, path: /dev/bus/usb/001/005
00000155 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x0451, PID: 0x8042, path: /dev/bus/usb/001/003
00000125 winscard_msg_srv.c:251:ProcessEventsServer() Common channel packet arrival
00000031 winscard_msg_srv.c:263:ProcessEventsServer() ProcessCommonChannelRequest detects: 8
00000008 pcscdaemon.c:131:SVCServiceRunLoop() A new context thread creation is requested: 8
00000658 winscard_svc.c:340:ContextThread() Authorized PC/SC client
00000110 winscard_svc.c:344:ContextThread() Thread is started: dwClientID=8, threadContext @0xef4d40
00000067 winscard_svc.c:362:ContextThread() Received command: CMD_VERSION from client 8
00000044 winscard_svc.c:374:ContextThread() Client is protocol version 4:3
00000051 winscard_svc.c:394:ContextThread() CMD_VERSION rv=0x0 for client 8
00000153 winscard_svc.c:362:ContextThread() Received command: ESTABLISH_CONTEXT from client 8
00000087 winscard.c:215:SCardEstablishContext() Establishing Context: 0x1E211712
00000059 winscard_svc.c:458:ContextThread() ESTABLISH_CONTEXT rv=0x0 for client 8
00000079 winscard_svc.c:362:ContextThread() Received command: CMD_GET_READERS_STATE from client 8
00001207 hotplug_libudev.c:645:HPEstablishUSBNotifications() USB Device removed
00257770 hotplug_libudev.c:651:HPEstablishUSBNotifications() USB Device add
00000266 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x0783, PID: 0x0003, path: /dev/bus/usb/001/057
00000024 hotplug_libudev.c:436:HPAddDevice() Adding USB device: C3PO LTC3x USB
00000112 readerfactory.c:1074:RFInitializeReader() Attempting startup of C3PO LTC3x USB (00004390) 00 00 using /usr/lib/pcsc/drivers/ifd-ccid.bundle/Contents/Linux/libccid.so
00000735 readerfactory.c:949:RFBindFunctions() Loading IFD Handler 3.0
00000056 ifdhandler.c:1965:init_driver() Driver version: 1.4.27
00001208 ifdhandler.c:1982:init_driver() LogLevel: 0x0003
00000019 ifdhandler.c:1993:init_driver() DriverOptions: 0x0000
00000262 ifdhandler.c:111:CreateChannelByNameOrChannel() Lun: 0, device: usb:0783/0003:libudev:0:/dev/bus/usb/001/057
00000021 ccid_usb.c:302:OpenUSBByName() Using: /usr/lib/pcsc/drivers/ifd-ccid.bundle/Contents/Info.plist
00001066 ccid_usb.c:320:OpenUSBByName() ifdManufacturerString: Ludovic Rousseau (ludovic.rousseau@free.fr)
00000016 ccid_usb.c:321:OpenUSBByName() ifdProductString: Generic CCID driver
00000007 ccid_usb.c:322:OpenUSBByName() Copyright: This driver is protected by terms of the GNU Lesser General Public License version 2.1, or (at your option) any later version.
00016652 ccid_usb.c:656:OpenUSBByName() Found Vendor/Product: 0783/0003 (C3PO LTC3x USB)
00000102 ccid_usb.c:658:OpenUSBByName() Using USB bus/device: 1/57
00000068 ccid_usb.c:717:OpenUSBByName() bNumDataRatesSupported is 0
00114466 ifdhandler.c:382:IFDHGetCapabilities() tag: 0xFB3, usb:0783/0003:libudev:0:/dev/bus/usb/001/057 (lun: 0)
00000033 readerfactory.c:396:RFAddReader() Using the reader polling thread
00004091 ifdhandler.c:382:IFDHGetCapabilities() tag: 0xFAE, usb:0783/0003:libudev:0:/dev/bus/usb/001/057 (lun: 0)
00000033 ifdhandler.c:477:IFDHGetCapabilities() Reader supports 1 slot(s)
00602697 winscard_svc.c:362:ContextThread() Received command: CMD_GET_READERS_STATE from client 8
00019324 winscard_svc.c:362:ContextThread() Received command: CMD_GET_READERS_STATE from client 8
00040705 winscard_svc.c:362:ContextThread() Received command: CMD_GET_READERS_STATE from client 8
00000167 winscard_svc.c:362:ContextThread() Received command: CONNECT from client 8
00000016 winscard_svc.c:496:ContextThread() Authorized client for 'C3PO LTC3x USB (00004390) 00 00'
00000131 winscard.c:259:SCardConnect() Attempting Connect to C3PO LTC3x USB (00004390) 00 00 using protocol: 3
00000010 readerfactory.c:820:RFReaderInfo() RefReader() count was: 1
00000007 winscard.c:444:SCardConnect() Direct access: no protocol selected
00000009 winscard.c:456:SCardConnect() hCard Identity: 4663acc4
00000074 winscard.c:518:SCardConnect() UnrefReader() count was: 2
00000011 winscard_svc.c:510:ContextThread() CONNECT rv=0x0 for client 8
00000190 winscard_svc.c:362:ContextThread() Received command: CONTROL from client 8
00000026 readerfactory.c:847:RFReaderInfoById() RefReader() count was: 1
00000011 ifdhandler.c:1415:IFDHControl() ControlCode: 0x42000D48, usb:0783/0003:libudev:0:/dev/bus/usb/001/057 (lun: 0)
00000007 Control TxBuffer: 
00000017 Control RxBuffer: 12 04 42 33 00 12 

Some investigation reveals that there is some problem with the autosuspend. After 2 seconds of inactivity, the device automatically suspends, as configured by the power/autosupend parameter:

$ cat /sys/bus/usb/devices/1-3.2/power/{control,autosuspend}
auto
2

It can be observed that the state in power/runtime_status goes from active to suspended.

But then, when I try to read from the device, it doesn't respond, and a broken pipe (-EPIPE) error is produced:

$ od /dev/bus/usb/001/048
od: /dev/bus/usb/001/048: Broken pipe

From the Kernel documentation:

The USB specification states that all USB devices must support power
management.  Nevertheless, the sad fact is that many devices do not
support it very well.  You can suspend them all right, but when you
try to resume them they disconnect themselves from the USB bus or
they stop working entirely.  This seems to be especially prevalent
among printers and scanners, but plenty of other types of device have
the same deficiency.

For this reason, by default the kernel disables autosuspend (the
power/control attribute is initialized to "on") for all devices other
than hubs.  Hubs, at least, appear to be reasonably well-behaved in
this regard.

So it seems that the device doesn't support autosuspend. But the udev rule in 92_pcscd_ccid.rules forces the autosuspend parameter to "auto". Even if I try to overwrite the rule, by writing my own exception like:

$ cat /etc/udev/rules.d/99-usb-autosuspend.rules
ACTION=="add", SUBSYSTEM=="usb", TEST=="power/control", ATTR{idVendor}=="0783", ATTR{idProduct}=="0003", ATTR{power/control}="on"

It seems that the shell script in 92_pcscd_ccid.rules, is executed after my own rule, enabling once again the autosuspend:

ENV{ID_USB_INTERFACES}==":0b0000:", RUN+="/bin/sh -c 'echo auto > /sys/$devpath/power/control'"

By using the ATTR{power/control}="auto" command instead, it allows other rules to overwrite it's default behavior, (also tests that the file power/control exists):

ENV{ID_USB_INTERFACES}==":0b0000:", TEST=="power/control", ATTR{power/control}="auto"

Then I can use my own rules to overwrite the autosuspend, and thus fix the problem with my device.

It may be useful to detect if a device allows suspension, and then enable autosuspend. But keeping by default the autosuspend disabled, as it may be somewhat difficult to diagnostic in bogus devices.

[LudovicRousseau]

Hello,
You are the first one to report this problem. So I guess a lot of devices do support autosuspend.

I will test your proposed change. Thanks.

[LudovicRousseau]

Fixed in abed9df

I note that the reader you use is in the "Unsupported or partly supported CCID readers" list
http://pcsclite.alioth.debian.org/ccid/unsupported.html#0x07830x0003

Maybe I moved the reader in the unsupported list because the power autosuspend does not work correctly. If I can find such a reader in my reader stock I will try to see if your proposed change make the reader works reliably.

[LudovicRousseau]

On my Debian stable system (Linux 4.9.0-3) the USB autosuspend is not enabled. I don't know why.
I always have:

# cat 1-2/power/control
on

I also tried to set to "auto". In that case the reader is not suspended, even after 2 seconds. When a card is inserted the red LED is still switched on.

When I use od(1) to access the USB device as you did in your example I can see a lot of reader disconect/connect using dmesg -w. I think that using od(1) is not a good idea to test if the reader works. You can quit pcscd and start it again. In my case the reader is detected and is usable. No problem.

From your pcscd log I am not sure what your problem is. My interpretation is:

• you insert the reader but the driver fails to use it
• you remove the reader
• you insert the reader again and this time the driver can use it

Is my interpretation exact?
If yes, does your change to disable autosuspend solves the above problem?

[rodarima]

On my Debian stable system (Linux 4.9.0-3) the USB autosuspend is not enabled.
I don't know why.
I always have:

# cat 1-2/power/control
on

I'm using Arch Linux with the kernel 4.12.8-2, but I don't know if there is any
recent update in the usb drivers. You can use udevadm(8) to debug the rule
execution of your device:

# udevadm test /sys/bus/usb/devices/1-2

In my case, I can see both rules executed.

# udevadm test /sys/bus/usb/devices/1-3.2 2>&1 | grep control
ATTR '/sys/devices/pci0000:00/0000:00:02.1/usb1/1-3/1-3.2/power/control' writing 'auto' /usr/lib/udev/rules.d/92_pcscd_ccid.rules:16
ATTR '/sys/devices/pci0000:00/0000:00:02.1/usb1/1-3/1-3.2/power/control' writing 'on' /etc/udev/rules.d/99-usb-autosuspend.rules:1

You can also see the default values for autosuspend in the usbcore module, see
modinfo usbcore. In my system, here is what I have:

$ grep -R . /sys/module/usbcore/parameters/
/sys/module/usbcore/parameters/old_scheme_first:N
/sys/module/usbcore/parameters/usbfs_memory_mb:16
/sys/module/usbcore/parameters/usbfs_snoop:N
/sys/module/usbcore/parameters/usbfs_snoop_max:65536
/sys/module/usbcore/parameters/authorized_default:-1
/sys/module/usbcore/parameters/use_both_schemes:Y
/sys/module/usbcore/parameters/autosuspend:2
/sys/module/usbcore/parameters/nousb:N
/sys/module/usbcore/parameters/blinkenlights:N
/sys/module/usbcore/parameters/initial_descriptor_timeout:5000

I also tried to set to "auto". In that case the reader is not suspended, even
after 2 seconds. When a card is inserted the red LED is still switched on.

The device doesn't turn off, but the kernel sets the state to suspended. You can
see power/runtime_status to test the state. I can replicate your result
introducing a card in the device and commenting out my special udev rule:

1. With the device disconnected, I disable the pcscd.socket, so that the
   service is not going to be activated by others:

# systemctl stop pcscd.socket

2. Then I turn off the pcscd.service, killing the daemon:

$ pgrep pcscd
8512
# systemctl stop pcscd.service
$ pgrep pcscd
$

3. I set a loop to monitor the power/runtime_status

$ cd /sys/bus/usb/devices
$ while [ 1 ]; do cat 1-3.2/power/runtime_status; sleep 0.5; done
cat: 1-3.2/power/runtime_status: No such file or directory
cat: 1-3.2/power/runtime_status: No such file or directory
...

4. Now I plug the device with a card already inserted. The red LED is now on.

$ dmesg -t | tail -3
usb 1-3.2: new low-speed USB device number 10 using ehci-pci
usb 1-3.2: config 1 interface 0 altsetting 0 endpoint 0x2 is Bulk; changing to Interrupt
usb 1-3.2: config 1 interface 0 altsetting 0 endpoint 0x82 is Bulk; changing to Interrupt

The monitor loop shows:

...
cat: 1-3.2/power/runtime_status: No such file or directory
cat: 1-3.2/power/runtime_status: No such file or directory
active
active
active
active
active
suspended
suspended
...

The control is set to auto, as specified by udev:

# udevadm test /sys/bus/usb/devices/1-3.2 2>&1 | grep control
ATTR '/sys/devices/pci0000:00/0000:00:02.1/usb1/1-3/1-3.2/power/control' writing 'auto' /usr/lib/udev/rules.d/92_pcscd_ccid.rules:16
$ cd /sys/bus/usb/devices/1-3.2/
$ cat power/control
auto
$ cat power/runtime_status
suspended

The device has been suspended by the kernel, and the red LED is still on. But,
if you try to activate the device again, it will fail. You can use the
power/control attribute to activate the device, by writing "on":

$ echo on | sudo tee 1-3.2/power/control
$ dmesg -t | tail -5
usb 1-3.2: reset low-speed USB device number 10 using ehci-pci
usb 1-3.2: USB disconnect, device number 10
usb 1-3.2: new low-speed USB device number 11 using ehci-pci
usb 1-3.2: config 1 interface 0 altsetting 0 endpoint 0x2 is Bulk; changing to Interrupt
usb 1-3.2: config 1 interface 0 altsetting 0 endpoint 0x82 is Bulk; changing to Interrupt

Now the device has a number 11, and after 2 seconds will be suspended again. You
can also call open to /dev/bus/usb/001/011 to wake up the device. I traced
down the open call by reading the calls in libusb. First, in ccid_usb.c the
libusb_open function is called:

$ cat -n src/ccid_usb.c | sed -n '556p'
   556					r = libusb_open(dev, &dev_handle);

Which, in my system, calls usbi_backend->open which is set to op_open at
libusb/os/linux_usbfs.c:1283:

$ cat -n libusb/core.c | sed -n '1240p;1268p'
  1240	int API_EXPORTED libusb_open(libusb_device *dev,
  1268		r = usbi_backend->open(_dev_handle);

Then you can see the op_open calling _get_usbfs_fd to get a file descriptor:

$ cat -n libusb/os/linux_usbfs.c | sed -n '1283,1288p' 
  1283	static int op_open(struct libusb_device_handle *handle)
  1284	{
  1285		struct linux_device_handle_priv *hpriv = _device_handle_priv(handle);
  1286		int r;
  1287	
  1288		hpriv->fd = _get_usbfs_fd(handle->dev, O_RDWR, 0);

And the start of _get_usbfs_fd:

$ cat -n libusb/os/linux_usbfs.c | sed -n '183,197p'
   183	static int _get_usbfs_fd(struct libusb_device *dev, mode_t mode, 
	int silent)
   184	{
   185		struct libusb_context *ctx = DEVICE_CTX(dev);
   186		char path[PATH_MAX];
   187		int fd;
   188		int delay = 10000;
   189	
   190		if (usbdev_names)
   191			snprintf(path, PATH_MAX, "%s/usbdev%d.%d",
   192				usbfs_path, dev->bus_number, dev->device_address);
   193		else
   194			snprintf(path, PATH_MAX, "%s/%03d/%03d",
   195				usbfs_path, dev->bus_number, dev->device_address);
   196	
   197		fd = open(path, mode);

Which finally calls open(2).

I think that using od(1) is not a good idea to test if the reader works.

So by using od(1) I also call open, which already fails:

$ strace -e trace=open od /dev/bus/usb/001/011
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
open("/usr/lib/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
open("/dev/bus/usb/001/011", O_RDONLY)  = -1 EPIPE (Broken pipe)
...

When I use od(1) to access the USB device as you did in your example I can see
a lot of reader disconect/connect using dmesg -w.

Now you can see the exact same kernel log:

$ dmesg -t | tail -5
usb 1-3.2: reset low-speed USB device number 11 using ehci-pci
usb 1-3.2: USB disconnect, device number 11
usb 1-3.2: new low-speed USB device number 12 using ehci-pci
usb 1-3.2: config 1 interface 0 altsetting 0 endpoint 0x2 is Bulk; changing to Interrupt
usb 1-3.2: config 1 interface 0 altsetting 0 endpoint 0x82 is Bulk; changing to Interrupt

You can quit pcscd and start it again. In my case the reader is detected and
is usable. No problem.

In my case the reader also is usable, even with the libusb_open error. But is
just because after failing to open the device, the pcscd daemon keeps trying and
in the second try, the device is still active, as the 2 seconds for going to
suspended state have not yet elapsed.

You can test it by using a udev rule that sets the time for autosuspend to 0,
thus setting the device to suspension at the begining:

$ cat /etc/udev/rules.d/99-usb-autosuspend.rules
ACTION=="add", SUBSYSTEM=="usb", TEST=="power/autosuspend", ATTR{idVendor}=="0783", ATTR{idProduct}=="0003", ATTR{power/autosuspend}="0"

Then start the pcscd daemon, and you could see an endless loop of errors:

# /usr/bin/pcscd --debug --foreground --auto-exit | grep libusb_open
00634566 ccid_usb.c:560:OpenUSBByName() Can't libusb_open(1/53): LIBUSB_ERROR_IO
00637399 ccid_usb.c:560:OpenUSBByName() Can't libusb_open(1/54): LIBUSB_ERROR_IO
00633078 ccid_usb.c:560:OpenUSBByName() Can't libusb_open(1/55): LIBUSB_ERROR_IO
00633168 ccid_usb.c:560:OpenUSBByName() Can't libusb_open(1/56): LIBUSB_ERROR_IO
00000155 ccid_usb.c:560:OpenUSBByName() Can't libusb_open(1/57): LIBUSB_ERROR_IO
00638637 ccid_usb.c:560:OpenUSBByName() Can't libusb_open(1/58): LIBUSB_ERROR_IO
00643064 ccid_usb.c:560:OpenUSBByName() Can't libusb_open(1/59): LIBUSB_ERROR_IO
00635648 ccid_usb.c:560:OpenUSBByName() Can't libusb_open(1/60): LIBUSB_ERROR_IO

From your pcscd log I am not sure what your problem is. My interpretation is:

• you insert the reader but the driver fails to use it
• you remove the reader
• you insert the reader again and this time the driver can use it

Is my interpretation exact?

No, I never need to remove the reader, the open(2) call issued by libusb, when
the pcscd daemon calls libusb_open produces a error in the kernel, and the
device is reset, as seen in the kernel log:

usb 1-3.2: reset low-speed USB device number 11 using ehci-pci
usb 1-3.2: USB disconnect, device number 11
usb 1-3.2: new low-speed USB device number 12 using ehci-pci

Then in the second try, the pcscd daemon calls open(2) again, but in the
active state, so no problem is caused, and the reader is usable, as the kernel
keeps the device active as long as a file descriptor is opened, from the
documentation:

In addition, a device isn't considered idle so long as a program keeps
its usbfs file open, whether or not any I/O is going on.

If yes, does your change to disable autosuspend solves the above problem?

Yes, in conjuntion with my own rule, which overwrites the autosupend parameter,
keeping the device always active.

[LudovicRousseau]

I played with my C3PO LTC3x USB reader to reproduce your issue.
I start pcscd use the reader and then quit pcscd so that the reader moves in suspended mode (as confirmed by the value in [...]/power/runtime_status.
When I start pcscd again I see that the first use of the reader fails as you described. Then the kernel reset the device:

[5879621.416477] usb 3-4: reset low-speed USB device number 39 using xhci_hcd
[5879621.710848] usb 3-4: USB disconnect, device number 39
[5879621.828310] usb 3-4: new low-speed USB device number 40 using xhci_hcd
[5879621.973369] usb 3-4: config 1 interface 0 altsetting 0 endpoint 0x2 is Bulk; changing to Interrupt
[5879621.973372] usb 3-4: config 1 interface 0 altsetting 0 endpoint 0x82 is Bulk; changing to Interrupt
[5879621.977093] usb 3-4: New USB device found, idVendor=0783, idProduct=0003
[5879621.977096] usb 3-4: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[5879621.977098] usb 3-4: Product: LTC3x USB
[5879621.977099] usb 3-4: Manufacturer: C3PO
[5879621.977101] usb 3-4: SerialNumber: 00001177

So the previous USB device is disconnected and a new USB device is connected as can be seen in pcscd logs:

00000196 hotplug_libudev.c:645:HPEstablishUSBNotifications() USB Device removed
00281971 hotplug_libudev.c:651:HPEstablishUSBNotifications() USB Device add

My interpretation was that you removed the device but it was in fact a reset/re-enumeration by the kernel.
The "new" device is then opened and used by pcscd with no problem.

Summary:

• without your patch the reader is usable (but you get a device reset).
• with my patch in abed9df you can add a new udev rule to avoid device suspend

Do you want me to change something in pcsc-lite and/or libccid?

[rodarima]

Okay, thanks, that's what I meant.

I don't know if you plan to support this buggy old device (and replaced by the v2). But I saw a per specific rule in 92_pcscd_ccid.rules with a special treatment for a Kobil mIDentity device. So maybe it will be useful to add another rule to keep this device from reseting. I created a pull request with the specific rule after the general one.

[LudovicRousseau]

OK. I will test your patch and apply it if it works as expected.