Page MenuHome GnuPG
Create Task
Maniphest T2306

Rare smartcard errors with gnupg master
Closed, ResolvedPublic
Actions

Description

My last update was to 2.1.12-beta95 I've just encountered another error and will
update again to current master.

With GnuPG master I've seen some rare errors that it can't access my smartcard
anymore until I restart gpg-agent. I did not have such errors before the libusb
patch.
I'll use this issue to document the erorrs. Sometimes I did not have errors for
weeks. Yesterday I had an error and today again.

I'm using my smartcard for authentication and encryption / signing.

SPR 532 Reader with openpgp 2.1 smartcard.

Scdaemon log excerpt: (I've tried to sign something on 12:34 and this failed)

2016-04-05 11:54:37 scdaemon[3383] DBG: chan_5 -> OK
2016-04-05 12:05:37 scdaemon[3383] DBG: ccid-driver: usb_bulk_write error:
LIBUSB_ERROR_NO_DEVICE
2016-04-05 12:05:37 scdaemon[3383] updating reader 0 (-1) status: 0x0007->0x0000
(1->1)
2016-04-05 12:05:37 scdaemon[3383] sending signal 12 to client 3273
2016-04-05 12:34:18 scdaemon[3383] DBG: chan_5 <- SERIALNO
2016-04-05 12:34:18 scdaemon[3383] DBG: ccid-driver: using CCID reader 0
(ID=04E6:E003:21250809205470:0)
2016-04-05 12:34:18 scdaemon[3383] DBG: ccid-driver: idVendor: 04E6 idProduct:
E003 bcdDevice: 0510
2016-04-05 12:34:18 scdaemon[3383] DBG: ccid-driver: ChipCard Interface Descriptor:
2016-04-05 12:34:18 scdaemon[3383] DBG: ccid-driver: bLength 54
2016-04-05 12:34:18 scdaemon[3383] DBG: ccid-driver: bDescriptorType 33
2016-04-05 12:34:18 scdaemon[3383] DBG: ccid-driver: bcdCCID 1.00
2016-04-05 12:34:18 scdaemon[3383] DBG: ccid-driver: nMaxSlotIndex 0
2016-04-05 12:34:18 scdaemon[3383] DBG: ccid-driver: bVoltageSupport 1
5.0V
2016-04-05 12:34:18 scdaemon[3383] DBG: ccid-driver: dwProtocols 3
T=0 T=1
2016-04-05 12:34:18 scdaemon[3383] DBG: ccid-driver: dwDefaultClock 4000
2016-04-05 12:34:18 scdaemon[3383] DBG: ccid-driver: dwMaxiumumClock 8000
2016-04-05 12:34:18 scdaemon[3383] DBG: ccid-driver: bNumClockSupported 0
2016-04-05 12:34:18 scdaemon[3383] DBG: ccid-driver: dwDataRate 10753 bps
2016-04-05 12:34:18 scdaemon[3383] DBG: ccid-driver: dwMaxDataRate 344105 bps
2016-04-05 12:34:18 scdaemon[3383] DBG: ccid-driver: bNumDataRatesSupp. 0
2016-04-05 12:34:18 scdaemon[3383] DBG: ccid-driver: dwMaxIFSD 254
2016-04-05 12:34:18 scdaemon[3383] DBG: ccid-driver: dwSyncProtocols 00000000
2016-04-05 12:34:18 scdaemon[3383] DBG: ccid-driver: dwMechanical 00000000
2016-04-05 12:34:18 scdaemon[3383] DBG: ccid-driver: dwFeatures 000100BA
2016-04-05 12:34:18 scdaemon[3383] DBG: ccid-driver: Auto configuration
based on ATR (assumes auto voltage)
2016-04-05 12:34:18 scdaemon[3383] DBG: ccid-driver: Auto voltage selection
2016-04-05 12:34:18 scdaemon[3383] DBG: ccid-driver: Auto clock change
2016-04-05 12:34:18 scdaemon[3383] DBG: ccid-driver: Auto baud rate change
2016-04-05 12:34:18 scdaemon[3383] DBG: ccid-driver: Auto PPS made by CCID
2016-04-05 12:34:18 scdaemon[3383] DBG: ccid-driver: TPDU level exchange
2016-04-05 12:34:18 scdaemon[3383] DBG: ccid-driver: dwMaxCCIDMsgLen 270
2016-04-05 12:34:18 scdaemon[3383] DBG: ccid-driver: bClassGetResponse echo
2016-04-05 12:34:18 scdaemon[3383] DBG: ccid-driver: bClassEnvelope echo
2016-04-05 12:34:18 scdaemon[3383] DBG: ccid-driver: wlcdLayout none
2016-04-05 12:34:18 scdaemon[3383] DBG: ccid-driver: bPINSupport 3
verification modification
2016-04-05 12:34:18 scdaemon[3383] DBG: ccid-driver: bMaxCCIDBusySlots 1
2016-04-05 12:34:18 scdaemon[3383] DBG: ccid-driver: usb_claim_interface failed: -6
2016-04-05 12:34:18 scdaemon[3383] DBG: chan_5 -> ERR 100663404 Card error <SCD>
2016-04-05 12:34:18 scdaemon[3383] DBG: chan_5 <- RESTART
2016-04-05 12:34:18 scdaemon[3383] DBG: chan_5 -> OK

It kept failing with the same error afterwards. Killing gpg-agent fixed it.

In my syslog I see the following related messages:

Apr 5 12:05:36 esus kernel: [11052.036061] usb 4-1.2: USB disconnect, device
number 3
Apr 5 12:05:37 esus kernel: [11052.233066] usb 4-1.2: new full-speed USB device
number 4 using ehci-pci
Apr 5 12:05:37 esus kernel: [11052.335805] usb 4-1.2: New USB device found,
idVendor=04e6, idProduct=e003
Apr 5 12:05:37 esus kernel: [11052.335810] usb 4-1.2: New USB device strings:
Mfr=1, Product=2, SerialNumber=5
Apr 5 12:05:37 esus kernel: [11052.335813] usb 4-1.2: Product: SPRx32 USB Smart
Card Reader
Apr 5 12:05:37 esus kernel: [11052.335815] usb 4-1.2: Manufacturer: SCM
Microsystems Inc.
Apr 5 12:05:37 esus kernel: [11052.335817] usb 4-1.2: SerialNumber: 21250809205470
Apr 5 12:05:37 esus mtp-probe: checking bus 4, device 4:
"/sys/devices/pci0000:00/0000:00:1d.0/usb4/4-1/4-1.2"
Apr 5 12:05:37 esus mtp-probe: bus: 4, device: 4 was not an MTP device

Details

Version
master

Related Objects

Event Timeline

• aheinecke added projects: scd, gnupg, Bug Report.Apr 5 2016, 12:52 PM
• aheinecke set Version to master.
• aheinecke added subscribers: • gniibe, • aheinecke.
• werner added a subscriber: • werner.Apr 5 2016, 3:31 PM

Hardware problem? The "usb_claim_interface failed" error seems to be ENXIO (No
such device or address).

• aheinecke added a comment.Apr 5 2016, 3:43 PM

Probably a trigger for this, but if a hardware error is causing this it appears
to be recoverable by software otherwise why would restarting gpg-agent /
scdaemon help?

Before the changes to libusb from time to time i had to reenter my pin for
authentication although it should have been cached and in the syslog it showed
the usb disconnect / reconnect. But scdeamon recovered from that.

btw. I can't reproduce this problem if I just disconnect / reconnect the reader
that works as expected.

• gniibe added a comment.Apr 6 2016, 8:21 AM

Possible causes would be SUSPEND/RESUME of usb device.
Let me see about libusb implementation differences.

• gniibe claimed this task.Apr 6 2016, 8:21 AM
• gniibe added a comment.Apr 22 2016, 1:53 AM

I'm reading the implementation of new libusb.
If I guess correctly, the picture of the problem would be:

  • New libusb somehow caches (or uses cache of kernel's) USB device list structures.
  • When the device is plugged off/on (or hardware failures), the cache should be

updated.

  • GnuPG's ccid-driver possibly keeps using staled data of USB device list.

I'll check the implementation detail, and try fixing this.
I think that current ccid-driver with new libusb has an issue for memory leaks
for device list, so, it should be reviewed and modified anyway.

It would be good if we could have a reproducible scenario.

• aheinecke added a comment.Apr 25 2016, 6:53 PM

I can make "a" problem (not sure if it is "the" problem) reproducible with the
following command (as root):

AUTHFILE="/sys/bus/usb/devices/4-1.2/authorized" ; echo 0 > "$AUTHFILE" ; sleep
1 ; echo 1 > "$AUTHFILE"

This was based on:
http://askubuntu.com/questions/645/how-do-you-reset-a-usb-device-from-the-command-line/61165#61165

where 4-1.2 is the id of my reader. The error message in scdaemon log is
slightly different but the behavior is the same. It's in an error state until I
kill it.

• gniibe added a project: Restricted Project.Apr 28 2016, 5:53 AM

The particular problem of T2306 (aheinecke on Apr 25 2016, 06:53 PM / Roundup) has been fixed in cb4fee8.

I think that it was not always reproducible because it depends on timing (only
when it detected an error at bulk_in, the problem happened). I'm not sure if
the difference of old/new libusb mattered for this problem.

• gniibe added a comment.May 2 2016, 9:04 AM

Another problem has been fixed in 6677d8b.
I intentionally set up more hubs from computer to the device to cause an error.
When an error occurred, scdaemon continued to report "Card error", even after I
inserted the device directly to the computer.
Now, it returns "No such device" for severe errors, and scdaemon can recover
from such errors.

• aheinecke closed this task as Resolved.Jul 20 2016, 3:06 PM

My problems are resolved. I have not encountered a problem since your last
fixes. Although I sometimes have to reenter pin so I think the errors still
occur occassionally but gnupg recovers.

Thanks.

• aheinecke removed a project: Restricted Project.Jul 20 2016, 3:06 PM