search

LudovicRousseau / pcsc-tools

Some tools to be used with smart cards and PC/SC
https://pcsc-tools.apdu.fr/
GNU General Public License v2.0
185 stars 63 forks source link

pcsc_scan not detecting the cards unless I unplug and replug the reader #59

Closed juanddperez closed 2 years ago

juanddperez commented 2 years ago

On a Raspberry Pi 4 with Linux raspberrypi 5.10.103-v7l+ #1529 SMP Tue Mar 8 12:24:00 GMT 2022 armv7l GNU/Linux

Freshly installed (libusb-dev libusb++ libccid pcscd libpcsclite1 libpcsclite-dev libpcsc-perl pcsc-tools) once, I use the pcsc_scan it does not detect the ACS ACR122U card reader. The status shows:

Jun 23 20:40:39 raspberrypi systemd[1]: Started PC/SC Smart Card Daemon.
Jun 23 20:40:39 raspberrypi pcscd[606]: 00000000 ccid_usb.c:898:ReadUSB() read failed (1/3): -7 LIBUSB_ERROR_TIMEOUT
Jun 23 20:40:39 raspberrypi pcscd[606]: 00158269 ccid_usb.c:898:ReadUSB() read failed (1/3): -7 LIBUSB_ERROR_TIMEOUT
Jun 23 20:40:39 raspberrypi pcscd[606]: 00000039 ifdhandler.c:194:CreateChannelByNameOrChannel() failed
Jun 23 20:40:39 raspberrypi pcscd[606]: 00000807 readerfactory.c:1106:RFInitializeReader() Open Port 0x200000 Failed (usb:072f/2200:libudev:0:/dev/bus/usb/001/003)
Jun 23 20:40:39 raspberrypi pcscd[606]: 00000032 readerfactory.c:376:RFAddReader() ACS ACR122U PICC Interface init failed.
Jun 23 20:40:39 raspberrypi pcscd[606]: 00000339 hotplug_libudev.c:523:HPAddDevice() Failed adding USB device: ACS ACR122U PICC Interface
Jun 23 20:41:46 raspberrypi systemd[1]: pcscd.service: Succeeded.

But, once I unplug the wire and then replug it, it works!

● pcscd.service - PC/SC Smart Card Daemon
   Loaded: loaded (/lib/systemd/system/pcscd.service; indirect; vendor preset: enabled)
   Active: active (running) since Thu 2022-06-23 20:48:28 BST; 6s ago
     Docs: man:pcscd(8)
 Main PID: 634 (pcscd)
    Tasks: 5 (limit: 3720)
   CGroup: /system.slice/pcscd.service
           └─634 /usr/sbin/pcscd --foreground --auto-exit

Why is this happening?

LudovicRousseau commented 2 years ago

This reader "ACS ACR122U PICC Interface" is in the "Unsupported" list https://ccid.apdu.fr/ccid/unsupported.html#0x072F0x2200

So I am not very surprised it does not work as expected.

I would need a complete pcscd log as documented in https://ccid.apdu.fr/#support

juanddperez commented 2 years ago

Thanks @LudovicRousseau!

As I told you before, this happens only when Linux starts; once Linux starts if we unplug then replug the wire, it starts working normally.

:~$ /usr/sbin/pcscd --version
Copyright (C) 1999-2002 by David Corcoran <corcoran@musclecard.com>.
Copyright (C) 2001-2015 by Ludovic Rousseau <ludovic.rousseau@free.fr>.
Copyright (C) 2003-2004 by Damien Sauveron <sauveron@labri.fr>.
Report bugs to <pcsclite-muscle@lists.alioth.debian.org>.
Enabled features: Linux arm-unknown-linux-gnueabihf libsystemd serial usb libudev usbdropdir=/usr/lib/pcsc/drivers ipcdir=/var/run/pcscd configdir=/etc/reader.conf.d
:~$ sudo LIBCCID_ifdLogLevel=0x000F pcscd --foreground --debug --apdu --color | tee log.txt
00000000 debuglog.c:299:DebugLogSetLevel() debug level=debug
00000124 debuglog.c:320:DebugLogSetCategory() Debug options: APDU
00000020 [-1225039744] pcscdaemon.c:352:main() Force colored logs
00000227 [-1225039744] utils.c:82:GetDaemonPid() Can't open /var/run/pcscd/pcscd.pid: No such file or directory
00000513 [-1225039744] configfile.l:284:DBGetReaderListDir() Parsing conf directory: /etc/reader.conf.d
00000072 [-1225039744] configfile.l:360:DBGetReaderList() Parsing conf file: /etc/reader.conf.d/libccidtwin
00000209 [-1225039744] configfile.l:321:DBGetReaderListDir() Skipping non regular file: .
00000026 [-1225039744] configfile.l:321:DBGetReaderListDir() Skipping non regular file: ..
00000039 [-1225039744] pcscdaemon.c:662:main() pcsc-lite 1.8.24 daemon ready.
00021693 [-1225039744] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/001/001
00001425 [-1225039744] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/001/001
00001352 [-1225039744] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x2109, PID: 0x3431, path: /dev/bus/usb/001/002
00001415 [-1225039744] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x072F, PID: 0x2200, path: /dev/bus/usb/001/003
00000040 [-1225039744] hotplug_libudev.c:436:HPAddDevice() Adding USB device: ACS ACR122U PICC Interface
00000275 [-1225039744] readerfactory.c:1075:RFInitializeReader() Attempting startup of ACS ACR122U PICC Interface 00 00 using /usr/lib/pcsc/drivers/ifd-ccid.bundle/Contents/Linux/libccid.so
00001146 [-1225039744] readerfactory.c:950:RFBindFunctions() Loading IFD Handler 3.0
00000138 [-1225039744] ifdhandler.c:1961:init_driver() Driver version: 1.4.30
00004230 [-1225039744] ifdhandler.c:1978:init_driver() LogLevel: 0x0003
00000038 [-1225039744] ifdhandler.c:1989:init_driver() DriverOptions: 0x0000
00000882 [-1225039744] ifdhandler.c:2002:init_driver() LogLevel from LIBCCID_ifdLogLevel: 0x000F
00000028 [-1225039744] ifdhandler.c:110:CreateChannelByNameOrChannel() Lun: 0, device: usb:072f/2200:libudev:0:/dev/bus/usb/001/003
00000021 [-1225039744] ccid_usb.c:237:OpenUSBByName() Reader index: 0, Device: usb:072f/2200:libudev:0:/dev/bus/usb/001/003
00000044 [-1225039744] ccid_usb.c:269:OpenUSBByName() interface_number: 0
00000019 [-1225039744] ccid_usb.c:270:OpenUSBByName() usb bus/device: 1/3
00000019 [-1225039744] ccid_usb.c:302:OpenUSBByName() Using: /usr/lib/pcsc/drivers/ifd-ccid.bundle/Contents/Info.plist
00004029 [-1225039744] ccid_usb.c:320:OpenUSBByName() ifdManufacturerString: Ludovic Rousseau (ludovic.rousseau@free.fr)
00000034 [-1225039744] ccid_usb.c:321:OpenUSBByName() ifdProductString: Generic CCID driver
00000021 [-1225039744] 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.
00016819 [-1225039744] ccid_usb.c:406:OpenUSBByName() Try device: 1/3
00000042 [-1225039744] ccid_usb.c:416:OpenUSBByName() vid/pid : 072F/2200
00000019 [-1225039744] ccid_usb.c:483:OpenUSBByName() Checking device: 1/3
00000019 [-1225039744] ccid_usb.c:554:OpenUSBByName() Trying to open USB bus/device: 1/3
00236444 [-1225039744] ccid_usb.c:660:OpenUSBByName() Found Vendor/Product: 072F/2200 (ACS ACR122U PICC Interface)
00000019 [-1225039744] ccid_usb.c:662:OpenUSBByName() Using USB bus/device: 1/3
00000008 [-1225039744] ccid_usb.c:722:OpenUSBByName() bNumDataRatesSupported is 0
00004434 [-1225039744] ccid_usb.c:1306:InterruptRead() before (0)
00033011 [-1225039744] ccid_usb.c:1352:InterruptRead() after (0) (0)
00000017 [-1225039744] NotifySlotChange: 50 03
00000012 [-1225039744] -> 000000 65 00 00 00 00 00 00 00 00 00
00021952 [-1225039744] <- 000000 81 00 00 00 00 00 02 02 81 00
00000017 [-1225039744] -> 000000 65 00 00 00 00 00 01 00 00 00
00049896 [-1225039744] <- 000000 81 00 00 00 00 00 00 02 81 00
00000013 [-1225039744] ccid_usb.c:920:ReadUSB() Duplicate frame detected
00100263 [-1225039744] ccid_usb.c:898:ReadUSB() read failed (1/3): -7 LIBUSB_ERROR_TIMEOUT
00000019 [-1225039744] -> 000000 65 00 00 00 00 00 02 00 00 00
00007938 [-1225039744] <- 000000 81 00 00 00 00 00 01 02 81 00
00000012 [-1225039744] ccid_usb.c:920:ReadUSB() Duplicate frame detected
00100244 [-1225039744] ccid_usb.c:898:ReadUSB() read failed (1/3): -7 LIBUSB_ERROR_TIMEOUT
00000014 [-1225039744] ifdhandler.c:194:CreateChannelByNameOrChannel() failed
00000008 [-1225039744] ccid_usb.c:941:CloseUSB() Closing USB device: 1/3
00000011 [-1225039744] ccid_usb.c:951:CloseUSB() Last slot closed. Release resources
00000076 [-1225039744] ccid_usb.c:189:close_libusb_if_needed() libusb_exit
00000369 [-1225039744] readerfactory.c:1106:RFInitializeReader() Open Port 0x200000 Failed (usb:072f/2200:libudev:0:/dev/bus/usb/001/003)
00000016 [-1225039744] readerfactory.c:376:RFAddReader() ACS ACR122U PICC Interface init failed.
00000008 [-1225039744] readerfactory.c:610:RFRemoveReader() UnrefReader() count was: 1
00000016 [-1225039744] readerfactory.c:1126:RFUnInitializeReader() Attempting shutdown of ACS ACR122U PICC Interface 00 00.
00000007 [-1225039744] readerfactory.c:987:RFUnloadReader() Unloading reader driver.
00000142 [-1225039744] hotplug_libudev.c:523:HPAddDevice() Failed adding USB device: ACS ACR122U PICC Interface
00000646 [-1225039744] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x2109, PID: 0x3431, path: /dev/bus/usb/001/002
00001382 [-1225039744] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0003, path: /dev/bus/usb/002/001

Hope this makes sense!

LudovicRousseau commented 2 years ago

You are using the CCID driver version 1.4.30. Upgrade to version 1.5.0 and try again. https://packages.debian.org/bookworm/libccid

juanddperez commented 2 years ago

Thank you @LudovicRousseau, but still we're facing the same:

root@raspberrypi:/home/pi# sudo LIBCCID_ifdLogLevel=0x000F pcscd --foreground --debug --apdu --color | tee log.txt
00000000 debuglog.c:299:DebugLogSetLevel() debug level=debug
00000086 debuglog.c:320:DebugLogSetCategory() Debug options: APDU
00000020 [-1224806272] pcscdaemon.c:352:main() Force colored logs
00000259 [-1224806272] utils.c:82:GetDaemonPid() Can't open /var/run/pcscd/pcscd.pid: No such file or directory
00000876 [-1224806272] configfile.l:284:DBGetReaderListDir() Parsing conf directory: /etc/reader.conf.d
00000074 [-1224806272] configfile.l:360:DBGetReaderList() Parsing conf file: /etc/reader.conf.d/libccidtwin
00000334 [-1224806272] configfile.l:321:DBGetReaderListDir() Skipping non regular file: .
00000105 [-1224806272] configfile.l:321:DBGetReaderListDir() Skipping non regular file: ..
00000046 [-1224806272] pcscdaemon.c:662:main() pcsc-lite 1.8.24 daemon ready.
00025338 [-1224806272] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/001/001
00001700 [-1224806272] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/001/001
00001592 [-1224806272] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x2109, PID: 0x3431, path: /dev/bus/usb/001/002
00002000 [-1224806272] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x072F, PID: 0x2200, path: /dev/bus/usb/001/003
00000043 [-1224806272] hotplug_libudev.c:436:HPAddDevice() Adding USB device: ACS ACR122U PICC Interface
00000422 [-1224806272] readerfactory.c:1075:RFInitializeReader() Attempting startup of ACS ACR122U PICC Interface 00 00 using /usr/lib/pcsc/drivers/ifd-ccid.bundle/Contents/Linux/libccid.so
00001414 [-1224806272] readerfactory.c:950:RFBindFunctions() Loading IFD Handler 3.0
00000173 [-1224806272] ifdhandler.c:2071:init_driver() Driver version: 1.5.0
00006158 [-1224806272] ifdhandler.c:2088:init_driver() LogLevel: 0x0003
00000039 [-1224806272] ifdhandler.c:2099:init_driver() DriverOptions: 0x0000
00001373 [-1224806272] ifdhandler.c:2112:init_driver() LogLevel from LIBCCID_ifdLogLevel: 0x000F
00000029 [-1224806272] ifdhandler.c:110:CreateChannelByNameOrChannel() Lun: 0, device: usb:072f/2200:libudev:0:/dev/bus/usb/001/003
00000021 [-1224806272] ccid_usb.c:252:OpenUSBByName() Reader index: 0, Device: usb:072f/2200:libudev:0:/dev/bus/usb/001/003
00000104 [-1224806272] ccid_usb.c:284:OpenUSBByName() interface_number: 0
00000020 [-1224806272] ccid_usb.c:285:OpenUSBByName() usb bus/device: 1/3
00000019 [-1224806272] ccid_usb.c:317:OpenUSBByName() Using: /usr/lib/pcsc/drivers/ifd-ccid.bundle/Contents/Info.plist
00004880 [-1224806272] ccid_usb.c:335:OpenUSBByName() ifdManufacturerString: Ludovic Rousseau (ludovic.rousseau@free.fr)
00000039 [-1224806272] ccid_usb.c:336:OpenUSBByName() ifdProductString: Generic CCID driver
00000021 [-1224806272] ccid_usb.c:337: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.
00017471 [-1224806272] ccid_usb.c:421:OpenUSBByName() Try device: 1/3
00000043 [-1224806272] ccid_usb.c:431:OpenUSBByName() vid/pid : 072F/2200
00000018 [-1224806272] ccid_usb.c:502:OpenUSBByName() Checking device: 1/3
00000018 [-1224806272] ccid_usb.c:573:OpenUSBByName() Trying to open USB bus/device: 1/3
00233253 [-1224806272] ccid_usb.c:679:OpenUSBByName() Found Vendor/Product: 072F/2200 (ACS ACR122U PICC Interface)
00000021 [-1224806272] ccid_usb.c:681:OpenUSBByName() Using USB bus/device: 1/3
00000008 [-1224806272] ccid_usb.c:744:OpenUSBByName() bNumDataRatesSupported is 0
00004595 [-1224806272] ccid_usb.c:1473:InterruptRead() before (0), timeout: 100 ms
00032707 [-1224806272] ccid_usb.c:1519:InterruptRead() after (0) (0)
00000017 [-1224806272] NotifySlotChange: 50 03
00000011 [-1224806272] -> 000000 65 00 00 00 00 00 00 00 00 00
00022508 [-1224806272] <- 000000 81 00 00 00 00 00 02 02 81 00
00000015 [-1224806272] ccid_usb.c:1020:ReadUSB() Invalid frame detected
03000470 [-1224806272] ccid_usb.c:993:ReadUSB() read failed (1/3): LIBUSB_ERROR_TIMEOUT
00000054 [-1224806272] -> 000000 65 00 00 00 00 00 01 00 00 00
00077633 [-1224806272] <- 000000 81 00 00 00 00 00 00 02 81 00
00000032 [-1224806272] ccid_usb.c:1020:ReadUSB() Invalid frame detected
00100404 [-1224806272] ccid_usb.c:993:ReadUSB() read failed (1/3): LIBUSB_ERROR_TIMEOUT
00000044 [-1224806272] -> 000000 65 00 00 00 00 00 02 00 00 00
00000626 [-1224806272] <- 000000 81 00 00 00 00 00 01 02 81 00
00000030 [-1224806272] ccid_usb.c:1020:ReadUSB() Invalid frame detected
00100424 [-1224806272] ccid_usb.c:993:ReadUSB() read failed (1/3): LIBUSB_ERROR_TIMEOUT
00000037 [-1224806272] ifdhandler.c:202:CreateChannelByNameOrChannel() failed
00000019 [-1224806272] ccid_usb.c:1039:CloseUSB() Closing USB device: 1/3
00000029 [-1224806272] ccid_usb.c:1051:CloseUSB() Last slot closed. Release resources
00000214 [-1224806272] ccid_usb.c:204:close_libusb_if_needed() libusb_exit
00001290 [-1224806272] readerfactory.c:1106:RFInitializeReader() Open Port 0x200000 Failed (usb:072f/2200:libudev:0:/dev/bus/usb/001/003)
00000034 [-1224806272] readerfactory.c:376:RFAddReader() ACS ACR122U PICC Interface init failed.
00000019 [-1224806272] readerfactory.c:610:RFRemoveReader() UnrefReader() count was: 1
00000018 [-1224806272] readerfactory.c:1126:RFUnInitializeReader() Attempting shutdown of ACS ACR122U PICC Interface 00 00.
00000022 [-1224806272] readerfactory.c:987:RFUnloadReader() Unloading reader driver.
00000505 [-1224806272] hotplug_libudev.c:523:HPAddDevice() Failed adding USB device: ACS ACR122U PICC Interface
00001753 [-1224806272] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x2109, PID: 0x3431, path: /dev/bus/usb/001/002
00003491 [-1224806272] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0003, path: /dev/bus/usb/002/001
LudovicRousseau commented 2 years ago

The reader does answer with the correct sequence number, unless you reboot the reader doing unplug/replug. I suggest to use another reader model. You can also report the problem to ACS and hope for a fix.

juanddperez commented 2 years ago

Thank you @LudovicRousseau - will try that!