with system on openrc user pcscd who creation through ebuild haven't access to usb devices. Manually fixing: gpasswd -a pcscd usb
You suggest to inform the user with an einfo line or something like that, correct?
I think 90 percent stuff who worked through pcsc daemon is usb-connect devices so direct aggregation usb permission would be right choice
Hi all! This problem still exists with pcsc-lite-1.8.22 and pcsc-lite-1.8.23 (which seems to require systemd, though, and I don't know if the problem exists there at all) I've created two simple patches for both, but was only able to test with pcsc-lite-1.8.22 (no systemd here)
Created attachment 534858 [details, diff] diff for pcsc-lite-1.8.22 ebuild
Created attachment 534860 [details, diff] diff for pcsc-lite-1.8.23 ebuild
dup of bug#652884?
hard to say. error messages are the same. but I do have ccid installed, the udev rules are in place, my bInterfaceClass is also 0xb. But still it only works if the user pcscd is in the usb (not the plugdev) group. lsusb -v -d 072f:90cc Bus 001 Device 010: ID 072f:90cc Advanced Card Systems, Ltd ACR38 SmartCard Reader Device Descriptor: bLength 18 bDescriptorType 1 bcdUSB 1.10 bDeviceClass 0 bDeviceSubClass 0 bDeviceProtocol 0 bMaxPacketSize0 8 idVendor 0x072f Advanced Card Systems, Ltd idProduct 0x90cc ACR38 SmartCard Reader bcdDevice 1.00 iManufacturer 1 ACS iProduct 2 CCID USB Reader iSerial 0 bNumConfigurations 1 Configuration Descriptor: bLength 9 bDescriptorType 2 wTotalLength 93 bNumInterfaces 1 bConfigurationValue 1 iConfiguration 0 bmAttributes 0x80 (Bus Powered) MaxPower 100mA Interface Descriptor: bLength 9 bDescriptorType 4 bInterfaceNumber 0 bAlternateSetting 0 bNumEndpoints 3 bInterfaceClass 11 Chip/SmartCard bInterfaceSubClass 0 bInterfaceProtocol 0 iInterface 0 ChipCard Interface Descriptor: bLength 54 bDescriptorType 33 bcdCCID 1.00 nMaxSlotIndex 0 bVoltageSupport 7 5.0V 3.0V 1.8V dwProtocols 3 T=0 T=1 dwDefaultClock 4000 dwMaxiumumClock 4000 bNumClockSupported 0 dwDataRate 10752 bps dwMaxDataRate 344100 bps bNumDataRatesSupp. 0 dwMaxIFSD 247 dwSyncProtocols 00000000 dwMechanical 00000000 dwFeatures 00010030 Auto clock change Auto baud rate change TPDU level exchange dwMaxCCIDMsgLen 271 bClassGetResponse 00 bClassEnvelope 00 wlcdLayout none bPINSupport 0 bMaxCCIDBusySlots 1 Endpoint Descriptor: bLength 7 bDescriptorType 5 bEndpointAddress 0x81 EP 1 IN bmAttributes 3 Transfer Type Interrupt Synch Type None Usage Type Data wMaxPacketSize 0x0008 1x 8 bytes bInterval 16 Endpoint Descriptor: bLength 7 bDescriptorType 5 bEndpointAddress 0x02 EP 2 OUT bmAttributes 2 Transfer Type Bulk Synch Type None Usage Type Data wMaxPacketSize 0x0040 1x 64 bytes bInterval 0 Endpoint Descriptor: bLength 7 bDescriptorType 5 bEndpointAddress 0x82 EP 2 IN bmAttributes 2 Transfer Type Bulk Synch Type None Usage Type Data wMaxPacketSize 0x0040 1x 64 bytes bInterval 0 can't get debug descriptor: Resource temporarily unavailable Device Status: 0x0000 (Bus Powered)
Please: udevadm info <device-path> make sure that PCSCD=1, if not debug the rule using udevadm trigger.
# udevadm info /dev/bus/usb/001/011 P: /devices/pci0000:00/0000:00:14.0/usb1/1-1 N: bus/usb/001/011 E: BUSNUM=001 E: DEVNAME=/dev/bus/usb/001/011 E: DEVNUM=011 E: DEVPATH=/devices/pci0000:00/0000:00:14.0/usb1/1-1 E: DEVTYPE=usb_device E: DRIVER=usb E: ID_BUS=usb E: ID_MODEL=CCID_USB_Reader E: ID_MODEL_ENC=CCID\x20USB\x20Reader E: ID_MODEL_FROM_DATABASE=ACR38 SmartCard Reader E: ID_MODEL_ID=90cc E: ID_REVISION=0100 E: ID_SERIAL=ACS_CCID_USB_Reader E: ID_USB_INTERFACES=:0b0000: E: ID_VENDOR=ACS E: ID_VENDOR_ENC=ACS E: ID_VENDOR_FROM_DATABASE=Advanced Card Systems, Ltd E: ID_VENDOR_ID=072f E: MAJOR=189 E: MINOR=10 E: PRODUCT=72f/90cc/100 E: SUBSYSTEM=usb E: TYPE=0/0/0 E: USEC_INITIALIZED=46478078240
Played some more with/without hotplug. If pcscd is allowed to be hotplugged via udev, it works. If pcscd is not allowed to be hotplugged, but started from init (as I have done for years), it does not: Jun 4 21:19:01 precise pcscd[30485]: ccid_usb.c:560:OpenUSBByName() Can't libusb_open(1/13): LIBUSB_ERROR_ACCESS Jun 4 21:19:01 precise pcscd[30485]: ifdhandler.c:151:CreateChannelByNameOrChannel() failed Jun 4 21:19:01 precise pcscd[30485]: /var/tmp/portage/sys-apps/pcsc-lite-1.8.22/work/pcsc-lite-1.8.22/src/readerfactory.c:1105:RFInitializeReader() Open Port 0x200000 Failed (usb:072f/90cc:libudev:0:/dev/bus/usb/001/013) Jun 4 21:19:01 precise pcscd[30485]: /var/tmp/portage/sys-apps/pcsc-lite-1.8.22/work/pcsc-lite-1.8.22/src/readerfactory.c:376:RFAddReader() ACS ACR 38U-CCID init failed. Which, in retrospect, makes sense. So actually, a documentation/news item/post-merge message pointing out that hotplug is now the only way to use pcscd (or else add to usb group) would be handy. thanks for the help
Already there: --- if use udev; then elog "Hotplug support is provided by udev rules; you only need to tell" elog "the init system to hotplug it, by setting this variable in" elog "/etc/rc.conf:" elog "" elog " rc_hotplug=\"pcscd\"" fi ---
Yes, I saw that and failed to apply that information to my case. (as I had been using pcscd from init for way over 10 years). Actually the if statement would have made it clear. elog "Hotplug support is provided by udev rules. If your system uses udev," elog "you must tell the init system to hotplug it, ..." "
OK, I was too fast with that analysis. Actually, it works, but just one time. pcscd gets successfully hotplugged, the card works. If I remove the reader, I get an error from pcscd: Jun 4 21:47:18 precise kernel: usb 1-1: USB disconnect, device number 5 Jun 4 21:47:19 precise pcscd[2741]: ccid_usb.c:849:WriteUSB() write failed (1/5): -4 LIBUSB_ERROR_NO_DEVICE And from then on the old behaviour is back. pcscd keeps running after the reader has been removed and gives the same error messages as before when it is reinserted. Jun 4 21:47:25 precise kernel: usb 1-1: new full-speed USB device number 6 using xhci_hcd Jun 4 21:47:25 precise kernel: usb 1-1: New USB device found, idVendor=072f, idProduct=90cc Jun 4 21:47:25 precise kernel: usb 1-1: New USB device strings: Mfr=1, Product=2, SerialNumber=0 Jun 4 21:47:25 precise kernel: usb 1-1: Product: CCID USB Reader Jun 4 21:47:25 precise kernel: usb 1-1: Manufacturer: ACS Jun 4 21:47:25 precise mtp-probe[2965]: checking bus 1, device 6: "/sys/devices/pci0000:00/0000:00:14.0/usb1/1-1" Jun 4 21:47:25 precise mtp-probe[2965]: bus: 1, device: 6 was not an MTP device Jun 4 21:47:25 precise pcscd[2741]: ccid_usb.c:560:OpenUSBByName() Can't libusb_open(1/6): LIBUSB_ERROR_ACCESS Jun 4 21:47:25 precise pcscd[2741]: ifdhandler.c:151:CreateChannelByNameOrChannel() failed Jun 4 21:47:25 precise pcscd[2741]: /var/tmp/portage/sys-apps/pcsc-lite-1.8.22/work/pcsc-lite-1.8.22/src/readerfactory.c:1105:RFInitializeReader() Open Port 0x200000 Failed (usb:072f/90cc:libudev:0:/dev/bus/usb/001/006) Jun 4 21:47:25 precise pcscd[2741]: /var/tmp/portage/sys-apps/pcsc-lite-1.8.22/work/pcsc-lite-1.8.22/src/readerfactory.c:376:RFAddReader() ACS ACR 38U-CCID init failed.
If I add pcscd back to the usb group, the error goes away again. Which, again, makes sense.
the sequence: 1. ccid udev rule puts PCSCD=1 in environemnt 2. pcsc-lite udev rule changes the device group to pcscd 3. pcsc-lite udev rule single pcscd to reload please understand why you do not have PCSCD=1 in your udevadm info, which is probably the trigger for the failure.
# udevadm -n -v a="bInterfaceClass=0b" /sys/devices/pci0000:00/0000:00:14.0/usb1/1-1/1-1:1.0 but # udevadm trigger -a "bInterfaceClass=0b" does nothing And yet pcscd gets started when the token is inserted ... I'm giving up. usermod -a -G usb pcscd
Hi, Again, we need to debug why the app-crypt/ccid udev rules are not working for you. Please use the udevadm monitor and plugin the device to see what happens and why PCSCD=1 environment is not being set. It should be trivial if match the interface class. Regards,
mdadm monitor -p shows the udev add event (both from kernel and udev) which also sets PCSCD=1 on the udev event. The output is identical for OK and NOK cases. UDEV [236.145488] add /devices/pci0000:00/0000:00:14.0/usb1/1-1 (usb) ACTION=add BUSNUM=001 DEVNAME=/dev/bus/usb/001/009 DEVNUM=009 DEVPATH=/devices/pci0000:00/0000:00:14.0/usb1/1-1 DEVTYPE=usb_device ID_BUS=usb ID_MODEL=CCID_USB_Reader ID_MODEL_ENC=CCID\x20USB\x20Reader ID_MODEL_FROM_DATABASE=ACR38 SmartCard Reader ID_MODEL_ID=90cc ID_REVISION=0100 ID_SERIAL=ACS_CCID_USB_Reader ID_USB_INTERFACES=:0b0000: ID_VENDOR=ACS ID_VENDOR_ENC=ACS ID_VENDOR_FROM_DATABASE=Advanced Card Systems, Ltd ID_VENDOR_ID=072f MAJOR=189 MINOR=8 PCSCD=1 PRODUCT=72f/90cc/100 SEQNUM=3840 SUBSYSTEM=usb TYPE=0/0/0 USEC_INITIALIZED=6121601 As said before, udev does start pcscd if it is not running, and all works fine for one time (even if pcscd is not in the usb group). The device group does, however, not get changed to pcscd in any case. (Or it gets changed back to usb later again, which I cannot see. Maybe by the bind actions that follow the add?) And after un-/replugging the original error occurs again if not in group pcscd. If you can tell me where to look further, I will.
ok, so the ccid udev rule is working correctly, we see PCSCD=1 this means that the problem is somewhere the pcsc-lite udev rule. the rule[1] is trivial... not sure what can go wrong... please add logger command to the rule to see that it is executed. logger WORKS; export | logger; ls -la "${DEVNAME}" | logger; ... this may show us what happens... I can only guess that you have another rule that override the group assignment. [1] https://github.com/gentoo/gentoo/blob/master/sys-apps/pcsc-lite/files/99-pcscd-hotplug.rules
I put this into /lib/udev/rules.d/99-pcscd-hotplug.rules: ACTION=="add", ENV{PCSCD}=="1", GROUP="pcscd", RUN+="/usr/bin/logger WORKS; export | /usr/bin/logger; ls -la ${DEVNAME} | /usr/bin/logger; /bin/env IN_HOTPLUG=1 /etc/init.d/pcscd --quiet start" (In your syntax it gives an error about /lib/udev/logger not found, and also the quotes give errors, even if escaped) Now it does no longer start pcscd upon plugging in the token. No additional log messages are generated: Jun 7 13:26:48 precise kernel: usb 1-1: new full-speed USB device number 14 using xhci_hcd Jun 7 13:26:48 precise kernel: usb 1-1: New USB device found, idVendor=072f, idProduct=90cc, bcdDevice= 1.00 Jun 7 13:26:48 precise kernel: usb 1-1: New USB device strings: Mfr=1, Product=2, SerialNumber=0 Jun 7 13:26:48 precise kernel: usb 1-1: Product: CCID USB Reader Jun 7 13:26:48 precise kernel: usb 1-1: Manufacturer: ACS Jun 7 13:26:48 precise mtp-probe[17558]: checking bus 1, device 14: "/sys/devices/pci0000:00/0000:00:14.0/usb1/1-1" Jun 7 13:26:48 precise mtp-probe[17558]: bus: 1, device: 14 was not an MTP device Obviously the token does not work, it just fails silently.
I am truly sorry, I need your help here to sort out the syntax errors. what we need is to see environment when udev event is triggered and check the group and mode of the device. the udev messup with the PATH so it does not work simply, maybe best to have a script as a wrapper instead. something like: -ACTION=="add", ENV{PCSCD}=="1", GROUP="pcscd", RUN+="/bin/env IN_HOTPLUG=1 /etc/init.d/pcscd --quiet start" +ACTION=="add", ENV{PCSCD}=="1", GROUP="pcscd", RUN+="/bin/env IN_HOTPLUG=1 /tmp/mywrapper /etc/init.d/pcscd --quiet start" and have /tmp/mywrapper: --- #!/bin/sh { echo START export | sort ls -la "${DEVNAME}" echo END } 2>&1 | /usr/bin/logger exec "${@}" --- what we want to see is that the device is modified to have pcscd group and is group writable in this specific rule and then examine the device and see if some other rule reverted these changes.
Now with full path for all: --- #!/bin/sh { /bin/echo START export | /bin/sort /bin/ls -la "${DEVNAME}" /bin/echo END } 2>&1 | /usr/bin/logger exec "${@}" ---
No problem. Getting closer: Jun 7 14:36:27 precise kernel: usb 1-1: new full-speed USB device number 7 using xhci_hcd Jun 7 14:36:28 precise kernel: usb 1-1: New USB device found, idVendor=072f, idProduct=90cc, bcdDevice= 1.00 Jun 7 14:36:28 precise kernel: usb 1-1: New USB device strings: Mfr=1, Product=2, SerialNumber=0 Jun 7 14:36:28 precise kernel: usb 1-1: Product: CCID USB Reader Jun 7 14:36:28 precise kernel: usb 1-1: Manufacturer: ACS Jun 7 14:36:28 precise mtp-probe[3335]: checking bus 1, device 7: "/sys/devices/pci0000:00/0000:00:14.0/usb1/1-1" Jun 7 14:36:28 precise mtp-probe[3335]: bus: 1, device: 7 was not an MTP device Jun 7 14:36:28 precise root[3351]: START Jun 7 14:36:28 precise root[3351]: export ACTION="add" Jun 7 14:36:28 precise root[3351]: export BUSNUM="001" Jun 7 14:36:28 precise root[3351]: export DEVNAME="/dev/bus/usb/001/007" Jun 7 14:36:28 precise root[3351]: export DEVNUM="007" Jun 7 14:36:28 precise root[3351]: export DEVPATH="/devices/pci0000:00/0000:00:14.0/usb1/1-1" Jun 7 14:36:28 precise root[3351]: export DEVTYPE="usb_device" Jun 7 14:36:28 precise root[3351]: export ID_BUS="usb" Jun 7 14:36:28 precise root[3351]: export ID_MODEL="CCID_USB_Reader" Jun 7 14:36:28 precise root[3351]: export ID_MODEL_ENC="CCID\\x20USB\\x20Reader" Jun 7 14:36:28 precise root[3351]: export ID_MODEL_FROM_DATABASE="ACR38 SmartCard Reader" Jun 7 14:36:28 precise root[3351]: export ID_MODEL_ID="90cc" Jun 7 14:36:28 precise root[3351]: export ID_REVISION="0100" Jun 7 14:36:28 precise root[3351]: export ID_SERIAL="ACS_CCID_USB_Reader" Jun 7 14:36:28 precise root[3351]: export ID_USB_INTERFACES=":0b0000:" Jun 7 14:36:28 precise root[3351]: export ID_VENDOR="ACS" Jun 7 14:36:28 precise root[3351]: export ID_VENDOR_ENC="ACS" Jun 7 14:36:28 precise root[3351]: export ID_VENDOR_FROM_DATABASE="Advanced Card Systems, Ltd" Jun 7 14:36:28 precise root[3351]: export ID_VENDOR_ID="072f" Jun 7 14:36:28 precise root[3351]: export IN_HOTPLUG="1" Jun 7 14:36:28 precise root[3351]: export MAJOR="189" Jun 7 14:36:28 precise root[3351]: export MINOR="6" Jun 7 14:36:28 precise root[3351]: export OLDPWD Jun 7 14:36:28 precise root[3351]: export PCSCD="1" Jun 7 14:36:28 precise root[3351]: export PRODUCT="72f/90cc/100" Jun 7 14:36:28 precise root[3351]: export PWD="/" Jun 7 14:36:28 precise root[3351]: export SEQNUM="3861" Jun 7 14:36:28 precise root[3351]: export SHLVL="1" Jun 7 14:36:28 precise root[3351]: export SUBSYSTEM="usb" Jun 7 14:36:28 precise root[3351]: export TYPE="0/0/0" Jun 7 14:36:28 precise root[3351]: export USEC_INITIALIZED="114293268" Jun 7 14:36:28 precise root[3351]: crw-rw-r-- 1 root pcscd 189, 6 Jun 7 14:36 /dev/bus/usb/001/007 Jun 7 14:36:28 precise root[3351]: ENDJun 7 14:36:28 precise start-stop-daemon[3380]: pam_unix(start-stop-daemon:session): session opened for user pcscd by (uid=0) So this rule works as well, the device's group gets set correctly. But afterwards, something must change it again: precise ~ # ls -l /dev/bus/usb/001/007 crw-rw---- 1 root usb 189, 6 Jun 7 14:36 /dev/bus/usb/001/007 My guess is that one of the other events triggers another rule. Here's the complete output of udevadm monitor -p: KERNEL[358.111204] add /devices/pci0000:00/0000:00:14.0/usb1/1-1 (usb) ACTION=add BUSNUM=001 DEVNAME=/dev/bus/usb/001/008 DEVNUM=008 DEVPATH=/devices/pci0000:00/0000:00:14.0/usb1/1-1 DEVTYPE=usb_device MAJOR=189 MINOR=7 PRODUCT=72f/90cc/100 SEQNUM=3869 SUBSYSTEM=usb TYPE=0/0/0 KERNEL[358.112801] add /devices/pci0000:00/0000:00:14.0/usb1/1-1/1-1:1.0 (usb) ACTION=add DEVPATH=/devices/pci0000:00/0000:00:14.0/usb1/1-1/1-1:1.0 DEVTYPE=usb_interface INTERFACE=11/0/0 MODALIAS=usb:v072Fp90CCd0100dc00dsc00dp00ic0Bisc00ip00in00 PRODUCT=72f/90cc/100 SEQNUM=3870 SUBSYSTEM=usb TYPE=0/0/0 KERNEL[358.112906] bind /devices/pci0000:00/0000:00:14.0/usb1/1-1 (usb) ACTION=bind BUSNUM=001 DEVNAME=/dev/bus/usb/001/008 DEVNUM=008 DEVPATH=/devices/pci0000:00/0000:00:14.0/usb1/1-1 DEVTYPE=usb_device DRIVER=usb MAJOR=189 MINOR=7 PRODUCT=72f/90cc/100 SEQNUM=3871 SUBSYSTEM=usb TYPE=0/0/0 UDEV [358.149274] add /devices/pci0000:00/0000:00:14.0/usb1/1-1 (usb) ACTION=add BUSNUM=001 DEVNAME=/dev/bus/usb/001/008 DEVNUM=008 DEVPATH=/devices/pci0000:00/0000:00:14.0/usb1/1-1 DEVTYPE=usb_device ID_BUS=usb ID_MODEL=CCID_USB_Reader ID_MODEL_ENC=CCID\x20USB\x20Reader ID_MODEL_FROM_DATABASE=ACR38 SmartCard Reader ID_MODEL_ID=90cc ID_REVISION=0100 ID_SERIAL=ACS_CCID_USB_Reader ID_USB_INTERFACES=:0b0000: ID_VENDOR=ACS ID_VENDOR_ENC=ACS ID_VENDOR_FROM_DATABASE=Advanced Card Systems, Ltd ID_VENDOR_ID=072f MAJOR=189 MINOR=7 PCSCD=1 PRODUCT=72f/90cc/100 SEQNUM=3869 SUBSYSTEM=usb TYPE=0/0/0 USEC_INITIALIZED=8120364 UDEV [358.149898] add /devices/pci0000:00/0000:00:14.0/usb1/1-1/1-1:1.0 (usb) ACTION=add DEVPATH=/devices/pci0000:00/0000:00:14.0/usb1/1-1/1-1:1.0 DEVTYPE=usb_interface ID_MODEL_FROM_DATABASE=ACR38 SmartCard Reader ID_VENDOR_FROM_DATABASE=Advanced Card Systems, Ltd INTERFACE=11/0/0 MODALIAS=usb:v072Fp90CCd0100dc00dsc00dp00ic0Bisc00ip00in00 PRODUCT=72f/90cc/100 SEQNUM=3870 SUBSYSTEM=usb TYPE=0/0/0 USEC_INITIALIZED=8149748 KERNEL[358.153653] bind /devices/pci0000:00/0000:00:14.0/usb1/1-1/1-1:1.0 (usb) ACTION=bind DEVPATH=/devices/pci0000:00/0000:00:14.0/usb1/1-1/1-1:1.0 DEVTYPE=usb_interface DRIVER=usbfs INTERFACE=11/0/0 MODALIAS=usb:v072Fp90CCd0100dc00dsc00dp00ic0Bisc00ip00in00 PRODUCT=72f/90cc/100 SEQNUM=3872 SUBSYSTEM=usb TYPE=0/0/0 UDEV [358.159764] bind /devices/pci0000:00/0000:00:14.0/usb1/1-1 (usb) ACTION=bind BUSNUM=001 DEVNAME=/dev/bus/usb/001/008 DEVNUM=008 DEVPATH=/devices/pci0000:00/0000:00:14.0/usb1/1-1 DEVTYPE=usb_device DRIVER=usb ID_BUS=usb ID_MODEL=CCID_USB_Reader ID_MODEL_ENC=CCID\x20USB\x20Reader ID_MODEL_FROM_DATABASE=ACR38 SmartCard Reader ID_MODEL_ID=90cc ID_REVISION=0100 ID_SERIAL=ACS_CCID_USB_Reader ID_USB_INTERFACES=:0b0000: ID_VENDOR=ACS ID_VENDOR_ENC=ACS ID_VENDOR_FROM_DATABASE=Advanced Card Systems, Ltd ID_VENDOR_ID=072f MAJOR=189 MINOR=7 PRODUCT=72f/90cc/100 SEQNUM=3871 SUBSYSTEM=usb TYPE=0/0/0 USEC_INITIALIZED=8120364 UDEV [358.160236] bind /devices/pci0000:00/0000:00:14.0/usb1/1-1/1-1:1.0 (usb) ACTION=bind DEVPATH=/devices/pci0000:00/0000:00:14.0/usb1/1-1/1-1:1.0 DEVTYPE=usb_interface DRIVER=usbfs ID_MODEL_FROM_DATABASE=ACR38 SmartCard Reader ID_VENDOR_FROM_DATABASE=Advanced Card Systems, Ltd INTERFACE=11/0/0 MODALIAS=usb:v072Fp90CCd0100dc00dsc00dp00ic0Bisc00ip00in00 PRODUCT=72f/90cc/100 SEQNUM=3872 SUBSYSTEM=usb TYPE=0/0/0 USEC_INITIALIZED=8149748
as expected, you have another rule on your system that reverts permissions set properly by the ccid/pcsc-lite. you may like to run udevd with debug log level to see what actually happens.
Jun 7 15:17:59 precise kernel: usb 1-1: new full-speed USB device number 8 using xhci_hcd Jun 7 15:17:59 precise kernel: usb 1-1: New USB device found, idVendor=072f, idProduct=90cc, bcdDevice= 1.00 Jun 7 15:17:59 precise kernel: usb 1-1: New USB device strings: Mfr=1, Product=2, SerialNumber=0 Jun 7 15:17:59 precise kernel: usb 1-1: Product: CCID USB Reader Jun 7 15:17:59 precise kernel: usb 1-1: Manufacturer: ACS Jun 7 15:17:59 precise kernel: udevd[637]: Validate module index Jun 7 15:17:59 precise kernel: udevd[637]: seq 3957 queued, 'add' 'usb' Jun 7 15:17:59 precise kernel: udevd[637]: seq 3957 forked new worker [3479] Jun 7 15:17:59 precise kernel: udevd[3479]: seq 3957 running Jun 7 15:17:59 precise kernel: udevd[3479]: no db file to read /run/udev/data/c189:7: No such file or directory Jun 7 15:17:59 precise kernel: udevd[3479]: RUN '/lib/udev/VBoxCreateUSBNode.sh $major $minor $attr{bDeviceClass}' /lib64/udev/rules.d/10-virtualbox.rules:5 >>> Jun 7 15:17:59 precise kernel: udevd[3479]: GROUP 85 /lib64/udev/rules.d/40-gentoo.rules:7 <<<< Jun 7 15:17:59 precise kernel: udevd[637]: seq 3958 queued, 'add' 'usb' Jun 7 15:17:59 precise kernel: udevd[637]: seq 3959 queued, 'bind' 'usb' Jun 7 15:17:59 precise kernel: udevd[3479]: IMPORT builtin 'usb_id' /lib64/udev/rules.d/50-udev-default.rules:13 Jun 7 15:17:59 precise mtp-probe[3481]: checking bus 1, device 8: "/sys/devices/pci0000:00/0000:00:14.0/usb1/1-1" Jun 7 15:17:59 precise mtp-probe[3481]: bus: 1, device: 8 was not an MTP device Jun 7 15:17:59 precise root[3497]: START Jun 7 15:17:59 precise root[3497]: export ACTION="add" Jun 7 15:17:59 precise root[3497]: export BUSNUM="001" Jun 7 15:17:59 precise root[3497]: export DEVNAME="/dev/bus/usb/001/008" Jun 7 15:17:59 precise root[3497]: export DEVNUM="008" Jun 7 15:17:59 precise root[3497]: export DEVPATH="/devices/pci0000:00/0000:00:14.0/usb1/1-1" Jun 7 15:17:59 precise root[3497]: export DEVTYPE="usb_device" Jun 7 15:17:59 precise root[3497]: export ID_BUS="usb" Jun 7 15:17:59 precise root[3497]: export ID_MODEL="CCID_USB_Reader" Jun 7 15:17:59 precise root[3497]: export ID_MODEL_ENC="CCID\\x20USB\\x20Reader" Jun 7 15:17:59 precise root[3497]: export ID_MODEL_FROM_DATABASE="ACR38 SmartCard Reader" Jun 7 15:17:59 precise root[3497]: export ID_MODEL_ID="90cc" Jun 7 15:17:59 precise root[3497]: export ID_REVISION="0100" Jun 7 15:17:59 precise root[3497]: export ID_SERIAL="ACS_CCID_USB_Reader" Jun 7 15:17:59 precise root[3497]: export ID_USB_INTERFACES=":0b0000:" Jun 7 15:17:59 precise root[3497]: export ID_VENDOR="ACS" Jun 7 15:17:59 precise root[3497]: export ID_VENDOR_ENC="ACS" Jun 7 15:17:59 precise root[3497]: export ID_VENDOR_FROM_DATABASE="Advanced Card Systems, Ltd" Jun 7 15:17:59 precise root[3497]: export ID_VENDOR_ID="072f" Jun 7 15:17:59 precise root[3497]: export IN_HOTPLUG="1" Jun 7 15:17:59 precise root[3497]: export MAJOR="189" Jun 7 15:17:59 precise root[3497]: export MINOR="7" Jun 7 15:17:59 precise root[3497]: export OLDPWD Jun 7 15:17:59 precise root[3497]: export PCSCD="1" Jun 7 15:17:59 precise root[3497]: export PRODUCT="72f/90cc/100" Jun 7 15:17:59 precise root[3497]: export PWD="/" Jun 7 15:17:59 precise root[3497]: export SEQNUM="3957" Jun 7 15:17:59 precise root[3497]: export SHLVL="1" Jun 7 15:17:59 precise root[3497]: export SUBSYSTEM="usb" Jun 7 15:17:59 precise root[3497]: export TYPE="0/0/0" Jun 7 15:17:59 precise root[3497]: export USEC_INITIALIZED="1347669363" Jun 7 15:17:59 precise root[3497]: crw-rw-r-- 1 root pcscd 189, 7 Jun 7 15:17 /dev/bus/usb/001/008 Jun 7 15:17:59 precise root[3497]: END /lib64/udev/rules.d/40-gentoo.rules already sets GROUP to 85 (usb). It seems that the GROUP from rule 99 is ignored, it does not appear in the udevd debug log. (/lib/udev/VBoxCreateUSBNode.sh creates devices in /dev/vboxusb and does nothing in /dev/usb)
The group from 99 is not ignored... Jun 7 15:17:59 precise root[3497]: crw-rw-r-- 1 root pcscd 189, 7 Jun 7 15:17 /dev/bus/usb/001/008 The rule is executed and has the desired affect. Something is running after that to revert.
agreed. So here's a fresh set of matching debug output Jun 7 16:32:49 precise kernel: usb 1-1: new full-speed USB device number 16 using xhci_hcd Jun 7 16:32:49 precise kernel: usb 1-1: New USB device found, idVendor=072f, idProduct=90cc, bcdDevice= 1.00 Jun 7 16:32:49 precise kernel: usb 1-1: New USB device strings: Mfr=1, Product=2, SerialNumber=0 Jun 7 16:32:49 precise kernel: usb 1-1: Product: CCID USB Reader Jun 7 16:32:49 precise kernel: usb 1-1: Manufacturer: ACS Jun 7 16:32:49 precise kernel: udevd[637]: Validate module index Jun 7 16:32:49 precise kernel: udevd[637]: seq 4146 queued, 'add' 'usb' Jun 7 16:32:49 precise kernel: udevd[637]: seq 4146 forked new worker [5007] Jun 7 16:32:49 precise kernel: udevd[5007]: seq 4146 running Jun 7 16:32:49 precise kernel: udevd[5007]: no db file to read /run/udev/data/c189:15: No such file or directory Jun 7 16:32:49 precise kernel: udevd[5007]: RUN '/lib/udev/VBoxCreateUSBNode.sh $major $minor $attr{bDeviceClass}' /lib64/udev/rules.d/10-virtualbox.rules:5 Jun 7 16:32:49 precise kernel: udevd[5007]: GROUP 85 /lib64/udev/rules.d/40-gentoo.rules:7 Jun 7 16:32:49 precise kernel: udevd[637]: seq 4147 queued, 'add' 'usb' Jun 7 16:32:49 precise kernel: udevd[637]: seq 4148 queued, 'bind' 'usb' Jun 7 16:32:49 precise kernel: udevd[5007]: IMPORT builtin 'usb_id' /lib64/udev/rules.d/50-udev-default.rules:13 Jun 7 16:32:49 precise mtp-probe[5008]: checking bus 1, device 16: "/sys/devices/pci0000:00/0000:00:14.0/usb1/1-1" Jun 7 16:32:49 precise mtp-probe[5008]: bus: 1, device: 16 was not an MTP device Jun 7 16:32:49 precise root[5024]: 5022 START Jun 7 16:32:49 precise root[5024]: export ACTION="add" Jun 7 16:32:49 precise root[5024]: export BUSNUM="001" Jun 7 16:32:49 precise root[5024]: export DEVNAME="/dev/bus/usb/001/016" Jun 7 16:32:49 precise root[5024]: export DEVNUM="016" Jun 7 16:32:49 precise root[5024]: export DEVPATH="/devices/pci0000:00/0000:00:14.0/usb1/1-1" Jun 7 16:32:49 precise root[5024]: export DEVTYPE="usb_device" Jun 7 16:32:49 precise root[5024]: export ID_BUS="usb" Jun 7 16:32:49 precise root[5024]: export ID_MODEL="CCID_USB_Reader" Jun 7 16:32:49 precise root[5024]: export ID_MODEL_ENC="CCID\\x20USB\\x20Reader" Jun 7 16:32:49 precise root[5024]: export ID_MODEL_FROM_DATABASE="ACR38 SmartCard Reader" Jun 7 16:32:49 precise root[5024]: export ID_MODEL_ID="90cc" Jun 7 16:32:49 precise root[5024]: export ID_REVISION="0100" Jun 7 16:32:49 precise root[5024]: export ID_SERIAL="ACS_CCID_USB_Reader" Jun 7 16:32:49 precise root[5024]: export ID_USB_INTERFACES=":0b0000:" Jun 7 16:32:49 precise root[5024]: export ID_VENDOR="ACS" Jun 7 16:32:49 precise root[5024]: export ID_VENDOR_ENC="ACS" Jun 7 16:32:49 precise root[5024]: export ID_VENDOR_FROM_DATABASE="Advanced Card Systems, Ltd" Jun 7 16:32:49 precise root[5024]: export ID_VENDOR_ID="072f" Jun 7 16:32:49 precise root[5024]: export IN_HOTPLUG="1" Jun 7 16:32:49 precise root[5024]: export MAJOR="189" Jun 7 16:32:49 precise root[5024]: export MINOR="15" Jun 7 16:32:49 precise root[5024]: export OLDPWD Jun 7 16:32:49 precise root[5024]: export PCSCD="1" Jun 7 16:32:49 precise root[5024]: export PRODUCT="72f/90cc/100" Jun 7 16:32:49 precise root[5024]: export PWD="/" Jun 7 16:32:49 precise root[5024]: export SEQNUM="4146" Jun 7 16:32:49 precise root[5024]: export SHLVL="1" Jun 7 16:32:49 precise root[5024]: export SUBSYSTEM="usb" Jun 7 16:32:49 precise root[5024]: export TYPE="0/0/0" Jun 7 16:32:49 precise root[5024]: export USEC_INITIALIZED="5837890168" Jun 7 16:32:49 precise root[5024]: crw-rw-r-- 1 root pcscd 189, 15 Jun 7 16:32 /dev/bus/usb/001/016 Jun 7 16:32:49 precise root[5024]: 5022 END mdadm monitor -p KERNEL[5837.877188] add /devices/pci0000:00/0000:00:14.0/usb1/1-1 (usb) ACTION=add BUSNUM=001 DEVNAME=/dev/bus/usb/001/016 DEVNUM=016 DEVPATH=/devices/pci0000:00/0000:00:14.0/usb1/1-1 DEVTYPE=usb_device MAJOR=189 MINOR=15 PRODUCT=72f/90cc/100 SEQNUM=4146 SUBSYSTEM=usb TYPE=0/0/0 KERNEL[5837.878806] add /devices/pci0000:00/0000:00:14.0/usb1/1-1/1-1:1.0 (usb) ACTION=add DEVPATH=/devices/pci0000:00/0000:00:14.0/usb1/1-1/1-1:1.0 DEVTYPE=usb_interface INTERFACE=11/0/0 MODALIAS=usb:v072Fp90CCd0100dc00dsc00dp00ic0Bisc00ip00in00 PRODUCT=72f/90cc/100 SEQNUM=4147 SUBSYSTEM=usb TYPE=0/0/0 KERNEL[5837.878964] bind /devices/pci0000:00/0000:00:14.0/usb1/1-1 (usb) ACTION=bind BUSNUM=001 DEVNAME=/dev/bus/usb/001/016 DEVNUM=016 DEVPATH=/devices/pci0000:00/0000:00:14.0/usb1/1-1 DEVTYPE=usb_device DRIVER=usb MAJOR=189 MINOR=15 PRODUCT=72f/90cc/100 SEQNUM=4148 SUBSYSTEM=usb TYPE=0/0/0 UDEV [5837.920175] add /devices/pci0000:00/0000:00:14.0/usb1/1-1 (usb) ACTION=add BUSNUM=001 DEVNAME=/dev/bus/usb/001/016 DEVNUM=016 DEVPATH=/devices/pci0000:00/0000:00:14.0/usb1/1-1 DEVTYPE=usb_device ID_BUS=usb ID_MODEL=CCID_USB_Reader ID_MODEL_ENC=CCID\x20USB\x20Reader ID_MODEL_FROM_DATABASE=ACR38 SmartCard Reader ID_MODEL_ID=90cc ID_REVISION=0100 ID_SERIAL=ACS_CCID_USB_Reader ID_USB_INTERFACES=:0b0000: ID_VENDOR=ACS ID_VENDOR_ENC=ACS ID_VENDOR_FROM_DATABASE=Advanced Card Systems, Ltd ID_VENDOR_ID=072f MAJOR=189 MINOR=15 PCSCD=1 PRODUCT=72f/90cc/100 SEQNUM=4146 SUBSYSTEM=usb TYPE=0/0/0 USEC_INITIALIZED=37890168 UDEV [5837.921284] add /devices/pci0000:00/0000:00:14.0/usb1/1-1/1-1:1.0 (usb) ACTION=add DEVPATH=/devices/pci0000:00/0000:00:14.0/usb1/1-1/1-1:1.0 DEVTYPE=usb_interface ID_MODEL_FROM_DATABASE=ACR38 SmartCard Reader ID_VENDOR_FROM_DATABASE=Advanced Card Systems, Ltd INTERFACE=11/0/0 MODALIAS=usb:v072Fp90CCd0100dc00dsc00dp00ic0Bisc00ip00in00 PRODUCT=72f/90cc/100 SEQNUM=4147 SUBSYSTEM=usb TYPE=0/0/0 USEC_INITIALIZED=37921045 UDEV [5837.931056] bind /devices/pci0000:00/0000:00:14.0/usb1/1-1 (usb) ACTION=bind BUSNUM=001 DEVNAME=/dev/bus/usb/001/016 DEVNUM=016 DEVPATH=/devices/pci0000:00/0000:00:14.0/usb1/1-1 DEVTYPE=usb_device DRIVER=usb ID_BUS=usb ID_MODEL=CCID_USB_Reader ID_MODEL_ENC=CCID\x20USB\x20Reader ID_MODEL_FROM_DATABASE=ACR38 SmartCard Reader ID_MODEL_ID=90cc ID_REVISION=0100 ID_SERIAL=ACS_CCID_USB_Reader ID_USB_INTERFACES=:0b0000: ID_VENDOR=ACS ID_VENDOR_ENC=ACS ID_VENDOR_FROM_DATABASE=Advanced Card Systems, Ltd ID_VENDOR_ID=072f MAJOR=189 MINOR=15 PRODUCT=72f/90cc/100 SEQNUM=4148 SUBSYSTEM=usb TYPE=0/0/0 USEC_INITIALIZED=37890168 What I don't understand: Jun 7 16:32:49 precise kernel: udevd[637]: seq 4146 queued, 'add' 'usb' Jun 7 16:32:49 precise kernel: udevd[637]: seq 4146 forked new worker [5007] Jun 7 16:32:49 precise kernel: udevd[5007]: seq 4146 running Jun 7 16:32:49 precise kernel: udevd[5007]: no db file to read /run/udev/data/c189:15: No such file or directory Jun 7 16:32:49 precise kernel: udevd[5007]: RUN '/lib/udev/VBoxCreateUSBNode.sh $major $minor $attr{bDeviceClass}' /lib64/udev/rules.d/10-virtualbox.rules:5 Jun 7 16:32:49 precise kernel: udevd[5007]: GROUP 85 /lib64/udev/rules.d/40-gentoo.rules:7 Jun 7 16:32:49 precise kernel: udevd[637]: seq 4147 queued, 'add' 'usb' Jun 7 16:32:49 precise kernel: udevd[637]: seq 4148 queued, 'bind' 'usb' - Which of the "add" events (seq 4146 or 4147) is triggering 99? And why is that not logged? - seq 4146 is for DEVTYPE=usb_device, 4147 for DEVTYPE=usb_interface. Additional magick here? - Could the bind event seq 4148 also trigger something? (Which maybe doesn't get logged for the same reason)
Do you run udev or eudev? How did you enabled log? most probably best is to set /etc/udev/udev.conf. Can you please reboot with log enabled and then check if you still do not see the RUN command? obviously, it is running as we see our wrapper running.
It's a fresh install with almost no customizations, without systemd (which is a no-go). Default in this configuration seems to be eudev, which is what I'm running. I 've set udev_debug="YES" in /etc/conf.d/udev and udev_log="debug" in /etc/udev/udev.conf, same result.
Hi eudev, Need your help here, maybe you can assist. We have the following two udev rules: https://github.com/gentoo/gentoo/blob/master/app-crypt/ccid/files/92_pcscd_ccid-2.rules https://github.com/gentoo/gentoo/blob/master/sys-apps/pcsc-lite/files/99-pcscd-hotplug.rules These rules seems to be running correctly. We added a debug wrapper to the pcscd rules, see comment#21. The udevd is placed in debug mode. In this system we see debug log of udev, but it does not match expectation, for example we do see the output of the wrapper but we do not see udev is executing its RUN statement, see comment#27. The problem to solve is what component reverts the group assignment of a usb device post of these rules, as the wrapper clearly shows that the assignment works. Thanks!
Please see if bug#666748, bug#667372 is relevant.
Created attachment 557934 [details] udevd --debug log while inserting card reader I'm not sure if I have the same problem, but it's a similar one, I guess. Running ``udevd --debug'', I noticed that 40-gentoo.rules is executed multiple times. This reverts the group setting to "usb", although it was previously set to "pcscd". I don't understand why eudev is reexecuting older rules (also 50-udev-default.rules and 10-virtualbox.rules). It just shouldn't do that. In my case, the permissions are setup correctly through /lib64/udev/rules.d/99-cyberjack.rules which is part of the cyberjack package. A workaround is to comment out the rule setting the device node's group to "usb" in /lib64/udev/rules.d/40-gentoo.rules, but then of course other devices' groups won't be changed either.
Comment on attachment 557934 [details] udevd --debug log while inserting card reader Setting attachment's MIME type to text/plain.
Created attachment 557936 [details] udevadm test $(udevadm info -q path -n /dev/bus/usb/001/028) And then it gets even weirder. While a normal plugging run lets udevd reexecuting previous rules for whatever reason I wasn't able to find out yet, calling 'udevadm test "$(udevadm info -q path -n /dev/bus/usb/001/028)"' is unable to reproduce this. Instead, rules are processed in the correct order and older rules *not* reexecuted. After that, the device node's permissions are correct. Log of that also attached. If the device is replugged afterwards, permissions are wrong again because of the "default" udevd rules processing that processed 40-gentoo.rules twice...
Note that I haven't actually tested hotplugging, since that never worked for me. It might work if the permissions were not messed up, but at least with eudev, I think they never did. I don't have a problem with spawning pcscd manually via the init script whenever I need it (and actually prefer doing so, since I can just turn it off when not needing it any longer). I figure that the general permissions problem is also affecting the hotplugging functionality, though.
eudev: please help.
I just noticed that this is an incarnation or duplicate of #668880. This bug is older, though, so I don't know how you want to handle this.
Hello from bug 668880. Yes, this and that bug seem to have similar problems, but I cannot say if this bug had originally the same or a different problem than what is presented in 668880. There is a critical date of 2017-11-12 that marks public release of kernel-4.14 and this bug has been opened before that, but the bug is also continued being investigated after that. There are two reasons behind "re-executing" the rules: 1) (e)udev merely passes any uevent from kernel to be processed by the rule files, 2) kernel 4.14 introduced new uevents bind/unbind to handle few obscure device firmware cases, see commit in [1]. Now, all of the rules-files are processed for every event. The event (ACTION-condition in the rules) may be be any of add, remove, change, move, online, offline, bind or unbind. If I am not mistaken of the purpose of the values in the kernel, these can be found in the ref [2]. So it is actually quite expected given how eudev 40-gentoo.rules is written [3], that when a device is plugged in it will cause the add-action to first set the devnode group to usb (by 40-gentoo) and later corrected to pcscd (by 99-pcscd-hotplug). After that the next event, bind, is processed and the ruleset 40-gentoo is again matching to the event (as there is no ACTION-matching) which resets the group to usb, and nothing else happens. The eudev 40-gentoo.rules (present in ebuild files dir [3]) should actually be compared to udev 40-gentoo.rules (present in actual ebuilds [4]). The notable difference is that eudev version never matches the ACTION where it should. Essentially it means, that even when devices are removed from system, their devnode group is needlessly set to a certain value. What I suggested in bug 668880, comment 7 is, that the ACTION would actually be matched for the ruleset so, that it is not executed blindly for all events but only for the relevant add-event, similarly to what is done in the udev ebuilds (or, more commonly, in any rule/ruleset present in the rules-directory). Note, that as is found in comment 32 that 10-virtualbox.rules are also executed multiple times, rule combination of { ACTION=="remove" -> expect we are in remove } + { ACTION!="remove" -> expect we are in add } is faulty and in my honest opinion should not be used. Instead the matching should be done in explicit way where we do not assume what different events can occur. Thus that would be { ACTION=="remove" -> expect remove } + { ACTION=="add" -> expect add }. So to finish up, I firstly and most importantly suggest, that the 40-gentoo rules are modified to only match on add-event (either by adding ACTION=="add" -match for each of the rules, or by jumping over the rules for all non-add events like is presented in attachment 557038 [details, diff] of bug 668880). Secondly I suggest to at least consider to sync and maybe move the ruleset to ebuild, to match with what is in udev-*.ebuild. After the 40-gentoo rules have been modified, the original bug here should be checked/challenged again. I would guess that any ebuild/rule changes to pcsc-lite are actually not required (or that the ones present currently in tree are sufficient). [1] https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/drivers/base/dd.c?id=1455cf8dbfd06aa7651dcfccbadb7a093944ca65 present in https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/tag/?h=v4.14 although even earlier in v4.14-rc1 dated 2017-09-16. [2] https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/tree/lib/kobject_uevent.c?id=4443f8e6ac7755cd775c70d08be8042dc2f936cb#n51 (a recent commit specified to keep the line number from accidentally pointing to a wrong line) [3] https://gitweb.gentoo.org/repo/gentoo.git/tree/sys-fs/eudev/files/40-gentoo.rules?id=56bd759df1d0c750a065b8c845e93d5dfa6b549d [4] https://gitweb.gentoo.org/repo/gentoo.git/tree/sys-fs/udev/udev-236-r1.ebuild?id=b448c9136c1116dc19ef31330af4ba81c02ee111#n89
