Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

ACR122U - Failed to transmit with protocol T0 #16

Closed
roaldnefs opened this issue Jun 9, 2019 · 5 comments
Closed

ACR122U - Failed to transmit with protocol T0 #16

roaldnefs opened this issue Jun 9, 2019 · 5 comments

Comments

@roaldnefs
Copy link

I'm currently running into the following error when : smartcard.Exceptions.CardConnectionException: Failed to transmit with protocol T0. Card protocol mismatch. on Ubuntu 19.04 with the ACR122U-A9.

Setup

$ sudo apt-get install pcscd pcsc-tools libacsccid1
$ sudo modprobe -r pn533_usb pn533 nfc
$ sudo service pcscd restart
$ sudo pip install pyscard

Both pcsc_scan and nfc-list work fine, but whenever I try to use pyscard I run into the following error: smartcard.Exceptions.CardConnectionException: Failed to transmit with protocol T0. Card protocol mismatch..

Workaround

After uninstalling the official ACS drivers and restarting the pcscd service it works as expected, e.g.:

# List the current installed drivers
$ dpkg --get-selections | grep libacsccid
libacsccid1

# Remove the driver
$ sudo dpkg -r libacsccid1

# Restart the pcscd service
$ sudo service pcscd restart

More Information

More information about this issue is available at: LudovicRousseau/pyscard#70.
@roaldnefs roaldnefs changed the title Failed to transmit with protocol T0 ACR122U - Failed to transmit with protocol T0 Jun 9, 2019
@godfreychung
Copy link
Contributor

Can you use the following command to generate the log file?
sudo LIBCCID_ifdLogLevel=0x0007 pcscd -fd | tee log.txt

@roaldnefs
Copy link
Author

@godfreychung, here is the output of the command: sudo LIBCCID_ifdLogLevel=0x0007 pcscd -fd:

00000000 debuglog.c:299:DebugLogSetLevel() debug level=debug
00000241 configfile.l:284:DBGetReaderListDir() Parsing conf directory: /etc/reader.conf.d
00000039 configfile.l:321:DBGetReaderListDir() Skipping non regular file: .
00000006 configfile.l:360:DBGetReaderList() Parsing conf file: /etc/reader.conf.d/libccidtwin
00000079 configfile.l:321:DBGetReaderListDir() Skipping non regular file: ..
00000014 pcscdaemon.c:662:main() pcsc-lite 1.8.24 daemon ready.
00009631 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/001/001
00000146 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/001/001
00000147 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x0CF3, PID: 0xE300, path: /dev/bus/usb/001/002
00000142 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x0CF3, PID: 0xE300, path: /dev/bus/usb/001/002
00000131 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/001/001
00000140 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x04F3, PID: 0x20D0, path: /dev/bus/usb/001/003
00000130 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/001/001
00000180 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x0BDA, PID: 0x568B, path: /dev/bus/usb/001/004
00000145 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x0BDA, PID: 0x568B, path: /dev/bus/usb/001/004
00000222 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0003, path: /dev/bus/usb/002/001
00000376 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/003/001
00000158 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/003/001
00000170 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x05E3, PID: 0x0610, path: /dev/bus/usb/003/002
00000179 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x214B, PID: 0x7000, path: /dev/bus/usb/003/003
00000188 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x072F, PID: 0x2200, path: /dev/bus/usb/003/022
00000007 hotplug_libudev.c:436:HPAddDevice() Adding USB device: ACS ACR122U PICC Interface
00000046 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
00000236 readerfactory.c:950:RFBindFunctions() Loading IFD Handler 3.0
00000025 ifdhandler.c:1961:init_driver() Driver version: 1.4.30
00000681 ifdhandler.c:1978:init_driver() LogLevel: 0x0003
00000007 ifdhandler.c:1989:init_driver() DriverOptions: 0x0000
00000212 ifdhandler.c:2002:init_driver() LogLevel from LIBCCID_ifdLogLevel: 0x0007
00000005 ifdhandler.c:110:CreateChannelByNameOrChannel() Lun: 0, device: usb:072f/2200:libudev:0:/dev/bus/usb/003/022
00000004 ccid_usb.c:237:OpenUSBByName() Reader index: 0, Device: usb:072f/2200:libudev:0:/dev/bus/usb/003/022
00000007 ccid_usb.c:269:OpenUSBByName() interface_number: 0
00000002 ccid_usb.c:270:OpenUSBByName() usb bus/device: 3/22
00000002 ccid_usb.c:302:OpenUSBByName() Using: /usr/lib/pcsc/drivers/ifd-ccid.bundle/Contents/Info.plist
00000656 ccid_usb.c:320:OpenUSBByName() ifdManufacturerString: Ludovic Rousseau (ludovic.rousseau@free.fr)
00000006 ccid_usb.c:321:OpenUSBByName() ifdProductString: Generic CCID driver
00000002 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.
00007953 ccid_usb.c:406:OpenUSBByName() Try device: 3/22
00000013 ccid_usb.c:416:OpenUSBByName() vid/pid : 072F/2200
00000004 ccid_usb.c:483:OpenUSBByName() Checking device: 3/22
00000003 ccid_usb.c:554:OpenUSBByName() Trying to open USB bus/device: 3/22
00074012 ccid_usb.c:660:OpenUSBByName() Found Vendor/Product: 072F/2200 (ACS ACR122U PICC Interface)
00000042 ccid_usb.c:662:OpenUSBByName() Using USB bus/device: 3/22
00000017 ccid_usb.c:722:OpenUSBByName() bNumDataRatesSupported is 0
00023108 NotifySlotChange: 50 03 
00000036 -> 000000 65 00 00 00 00 00 00 00 00 00 
00000618 <- 000000 81 00 00 00 00 00 00 00 81 00 
00000026 -> 000000 65 00 00 00 00 00 01 00 00 00 
00000574 <- 000000 81 00 00 00 00 00 01 00 81 00 
00000030 ifdhandler.c:381:IFDHGetCapabilities() tag: 0xFB3, usb:072f/2200:libudev:0:/dev/bus/usb/003/022 (lun: 0)
00000008 readerfactory.c:396:RFAddReader() Using the reader polling thread
00000860 ifdhandler.c:381:IFDHGetCapabilities() tag: 0xFAE, usb:072f/2200:libudev:0:/dev/bus/usb/003/022 (lun: 0)
00000027 ifdhandler.c:476:IFDHGetCapabilities() Reader supports 1 slot(s)
00001003 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x214B, PID: 0x7000, path: /dev/bus/usb/003/003
00000705 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x1038, PID: 0x1702, path: /dev/bus/usb/003/005
00000680 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x1038, PID: 0x1702, path: /dev/bus/usb/003/005
00000654 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x214B, PID: 0x7000, path: /dev/bus/usb/003/003
00000672 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x04D9, PID: 0x0169, path: /dev/bus/usb/003/006
00001058 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x04D9, PID: 0x0169, path: /dev/bus/usb/003/006
00000598 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x214B, PID: 0x7000, path: /dev/bus/usb/003/003
00000658 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x05E3, PID: 0x0610, path: /dev/bus/usb/003/002
00000664 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x05E3, PID: 0x0610, path: /dev/bus/usb/003/002
00000469 ifdhandler.c:1154:IFDHPowerICC() action: PowerUp, usb:072f/2200:libudev:0:/dev/bus/usb/003/022 (lun: 0)
00002631 -> 000000 62 00 00 00 00 00 05 01 00 00 
00001579 <- 000000 80 14 00 00 00 00 05 00 81 00 3B 8F 80 01 80 4F 0C A0 00 00 03 06 03 00 01 00 00 00 00 6A 
00000110 eventhandler.c:289:EHStatusHandlerThread() powerState: POWER_STATE_POWERED
00000097 Card ATR: 3B 8F 80 01 80 4F 0C A0 00 00 03 06 03 00 01 00 00 00 00 6A 
00000628 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0003, path: /dev/bus/usb/004/001
00008907 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0003, path: /dev/bus/usb/004/001
00000773 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x05E3, PID: 0x0617, path: /dev/bus/usb/004/002
00000760 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x0BDA, PID: 0x8153, path: /dev/bus/usb/004/003
00000711 hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x05E3, PID: 0x0617, path: /dev/bus/usb/004/002
00006461 NotifySlotChange: 50 03 
00000645 ifdhandler.c:1154:IFDHPowerICC() action: PowerDown, usb:072f/2200:libudev:0:/dev/bus/usb/003/022 (lun: 0)
00000027 -> 000000 63 00 00 00 00 00 08 00 00 00 
00000514 <- 000000 81 00 00 00 00 00 08 00 81 00 
00000043 eventhandler.c:482:EHStatusHandlerThread() powerState: POWER_STATE_UNPOWERED
00030753 NotifySlotChange: 50 03

Note: this is without libacsccid1 installed! Please let me know if you want the same output when I reinstall libacsccid1.

@godfreychung
Copy link
Contributor

Yes, please use libacsccid1 to reproduce the problem. I want to know the log when your script prints out the error message smartcard.Exceptions.CardConnectionException: Failed to transmit with protocol T0. Card protocol mismatch..

  1. sudo LIBCCID_ifdLogLevel=0x0007 pcscd -fd | tee log.txt
  2. Place a card on the reader.
  3. Run your script which uses pyscard.

@roaldnefs
Copy link
Author

Here is the output with libacsccid1 installed:

$ sudo LIBCCID_ifdLogLevel=0x0007 pcscd -fd
00000000 [140542259574720] debuglog.c:299:DebugLogSetLevel() debug level=debug
00000041 [140542259574720] utils.c:82:GetDaemonPid() Can't open /var/run/pcscd/pcscd.pid: No such file or directory
00000074 [140542259574720] configfile.l:284:DBGetReaderListDir() Parsing conf directory: /etc/reader.conf.d
00000013 [140542259574720] configfile.l:321:DBGetReaderListDir() Skipping non regular file: .
00000003 [140542259574720] configfile.l:360:DBGetReaderList() Parsing conf file: /etc/reader.conf.d/libccidtwin
00000035 [140542259574720] configfile.l:321:DBGetReaderListDir() Skipping non regular file: ..
00000006 [140542259574720] pcscdaemon.c:662:main() pcsc-lite 1.8.24 daemon ready.
00005336 [140542259574720] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/001/001
00000171 [140542259574720] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/001/001
00000154 [140542259574720] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x0CF3, PID: 0xE300, path: /dev/bus/usb/001/002
00000126 [140542259574720] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x0CF3, PID: 0xE300, path: /dev/bus/usb/001/002
00000124 [140542259574720] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/001/001
00000135 [140542259574720] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x04F3, PID: 0x20D0, path: /dev/bus/usb/001/003
00000104 [140542259574720] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/001/001
00000123 [140542259574720] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x0BDA, PID: 0x568B, path: /dev/bus/usb/001/004
00000118 [140542259574720] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x0BDA, PID: 0x568B, path: /dev/bus/usb/001/004
00000179 [140542259574720] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0003, path: /dev/bus/usb/002/001
00000396 [140542259574720] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/003/001
00000163 [140542259574720] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/003/001
00000148 [140542259574720] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x05E3, PID: 0x0610, path: /dev/bus/usb/003/002
00000150 [140542259574720] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x214B, PID: 0x7000, path: /dev/bus/usb/003/003
00000187 [140542259574720] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x072F, PID: 0x2200, path: /dev/bus/usb/003/005
00000007 [140542259574720] hotplug_libudev.c:436:HPAddDevice() Adding USB device: ACS ACR122U
00000051 [140542259574720] readerfactory.c:1075:RFInitializeReader() Attempting startup of ACS ACR122U 00 00 using /usr/lib/pcsc/drivers/ifd-acsccid.bundle/Contents/Linux/libacsccid.so
00000243 [140542259574720] readerfactory.c:950:RFBindFunctions() Loading IFD Handler 3.0
00000025 [140542259574720] ifdhandler.c:2930:init_driver() Driver version: 1.1.6
00000182 [140542259574720] ifdhandler.c:2947:init_driver() LogLevel: 0x0003
00000013 [140542259574720] ifdhandler.c:2958:init_driver() DriverOptions: 0x0000
00000006 [140542259574720] ifdhandler.c:2966:init_driver() ACSDriverOptions: 0x0003
00000005 [140542259574720] ifdhandler.c:2974:init_driver() ACR38CardVoltage: 0
00000011 [140542259574720] ifdhandler.c:2982:init_driver() ACR38CardType: 0
00000032 [140542259574720] ifdhandler.c:2995:init_driver() LogLevel from LIBCCID_ifdLogLevel: 0x0007
00000003 [140542259574720] ifdhandler.c:162:CreateChannelByNameOrChannel() Lun: 0, device: usb:072f/2200:libudev:0:/dev/bus/usb/003/005
00000005 [140542259574720] ccid_usb.c:263:OpenUSBByName() Reader index: 0, Device: usb:072f/2200:libudev:0:/dev/bus/usb/003/005
00000021 [140542259574720] ccid_usb.c:295:OpenUSBByName() interface_number: 0
00000004 [140542259574720] ccid_usb.c:296:OpenUSBByName() usb bus/device: 3/5
00000013 [140542259574720] ccid_usb.c:328:OpenUSBByName() Using: /usr/lib/pcsc/drivers/ifd-acsccid.bundle/Contents/Info.plist
00000173 [140542259574720] ccid_usb.c:346:OpenUSBByName() ifdManufacturerString: Advanced Card Systems Ltd.
00000005 [140542259574720] ccid_usb.c:347:OpenUSBByName() ifdProductString: ACS CCID driver
00000014 [140542259574720] ccid_usb.c:348: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.
00005333 [140542259574720] ccid_usb.c:432:OpenUSBByName() Try device: 3/5
00000008 [140542259574720] ccid_usb.c:442:OpenUSBByName() vid/pid : 072F/2200
00000002 [140542259574720] ccid_usb.c:526:OpenUSBByName() Checking device: 3/5
00000002 [140542259574720] ccid_usb.c:640:OpenUSBByName() Trying to open USB bus/device: 3/5
00066210 [140542259574720] ccid_usb.c:758:OpenUSBByName() Found Vendor/Product: 072F/2200 (ACS ACR122U)
00000019 [140542259574720] ccid_usb.c:760:OpenUSBByName() Using USB bus/device: 3/5
00000006 [140542259574720] ccid_usb.c:938:OpenUSBByName() bNumDataRatesSupported is 0
00000800 [140542259574720] -> 000000 63 00 00 00 00 00 00 00 00 00 
00000462 [140542259574720] <- 000000 81 00 00 00 00 00 00 02 81 00 
01015072 [140542259574720] NotifySlotChange: 50 02 
00000016 [140542259574720] ccid_usb.c:1835:InterruptRead() 3/5: Slot 0: 0x02
00000007 [140542259574720] -> 000000 65 00 00 00 00 00 01 00 00 00 
00000450 [140542259574720] <- 000000 81 00 00 00 00 00 01 02 81 00 
00000007 [140542259574720] ifdhandler.c:333:CreateChannelByNameOrChannel() dwFeatures: 0x00020040
00000002 [140542259574720] ifdhandler.c:334:CreateChannelByNameOrChannel() wLcdLayout: 0x0000
00000002 [140542259574720] ifdhandler.c:335:CreateChannelByNameOrChannel() bPINSupport: 0x00
00000002 [140542259574720] ifdhandler.c:336:CreateChannelByNameOrChannel() dwMaxCCIDMessageLength: 271
00000002 [140542259574720] ifdhandler.c:337:CreateChannelByNameOrChannel() dwMaxIFSD: 256
00000002 [140542259574720] ifdhandler.c:338:CreateChannelByNameOrChannel() dwDefaultClock: 4000
00000002 [140542259574720] ifdhandler.c:339:CreateChannelByNameOrChannel() dwMaxDataRate: 250000
00000001 [140542259574720] ifdhandler.c:340:CreateChannelByNameOrChannel() bMaxSlotIndex: 0
00000002 [140542259574720] ifdhandler.c:341:CreateChannelByNameOrChannel() bCurrentSlotIndex: 0
00000003 [140542259574720] ifdhandler.c:342:CreateChannelByNameOrChannel() bInterfaceProtocol: 0x00
00000003 [140542259574720] ifdhandler.c:343:CreateChannelByNameOrChannel() bNumEndpoints: 3
00000002 [140542259574720] ifdhandler.c:344:CreateChannelByNameOrChannel() bVoltageSupport: 0x07
00000004 [140542259574720] ifdhandler.c:510:IFDHGetCapabilities() tag: 0xFB3, usb:072f/2200:libudev:0:/dev/bus/usb/003/005 (lun: 0)
00000002 [140542259574720] readerfactory.c:396:RFAddReader() Using the reader polling thread
00000590 [140542259574720] ifdhandler.c:510:IFDHGetCapabilities() tag: 0xFAE, usb:072f/2200:libudev:0:/dev/bus/usb/003/005 (lun: 0)
00000006 [140542259574720] ifdhandler.c:613:IFDHGetCapabilities() Reader supports 1 slot(s)
00000268 [140542259574720] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x214B, PID: 0x7000, path: /dev/bus/usb/003/003
00000135 [140542259574720] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x1038, PID: 0x1702, path: /dev/bus/usb/003/006
00000158 [140542259574720] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x1038, PID: 0x1702, path: /dev/bus/usb/003/006
00000120 [140542259574720] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x214B, PID: 0x7000, path: /dev/bus/usb/003/003
00000128 [140542259574720] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x04D9, PID: 0x0169, path: /dev/bus/usb/003/007
00000149 [140542259574720] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x04D9, PID: 0x0169, path: /dev/bus/usb/003/007
00000123 [140542259574720] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x214B, PID: 0x7000, path: /dev/bus/usb/003/003
00000112 [140542259574720] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x05E3, PID: 0x0610, path: /dev/bus/usb/003/002
00000112 [140542259574720] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x05E3, PID: 0x0610, path: /dev/bus/usb/003/002
00000260 [140542259574720] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0003, path: /dev/bus/usb/004/001
00000109 [140542259574720] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0003, path: /dev/bus/usb/004/001
00000113 [140542259574720] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x05E3, PID: 0x0617, path: /dev/bus/usb/004/002
00000118 [140542259574720] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x0BDA, PID: 0x8153, path: /dev/bus/usb/004/003
00000113 [140542259574720] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x05E3, PID: 0x0617, path: /dev/bus/usb/004/002
00028888 [140542240433920] NotifySlotChange: 50 02 
00000026 [140542240433920] ccid_usb.c:1835:InterruptRead() 3/5: Slot 0: 0x02
08288135 [140542240433920] NotifySlotChange: 50 03 
00000021 [140542240433920] ccid_usb.c:1835:InterruptRead() 3/5: Slot 0: 0x00
00000927 [140542240433920] ifdhandler.c:1387:IFDHPowerICC() action: PowerUp, usb:072f/2200:libudev:0:/dev/bus/usb/003/005 (lun: 0)
00000010 [140542240433920] -> 000000 62 00 00 00 00 00 08 01 00 00 
00000922 [140542240433920] <- 000000 80 14 00 00 00 00 08 00 81 00 3B 8F 80 01 80 4F 0C A0 00 00 03 06 03 00 01 00 00 00 00 6A 
00000008 [140542240433920] eventhandler.c:406:EHStatusHandlerThread() powerState: POWER_STATE_POWERED
00000003 [140542240433920] eventhandler.c:423:EHStatusHandlerThread() Card inserted into ACS ACR122U 00 00
00000006 [140542240433920] Card ATR: 3B 8F 80 01 80 4F 0C A0 00 00 03 06 03 00 01 00 00 00 00 6A 
04577021 [140542259574720] winscard_msg_srv.c:255:ProcessEventsServer() Common channel packet arrival
00000022 [140542259574720] winscard_msg_srv.c:267:ProcessEventsServer() ProcessCommonChannelRequest detects: 14
00000006 [140542259574720] pcscdaemon.c:133:SVCServiceRunLoop() A new context thread creation is requested: 14
00000058 [140542223648512] winscard_svc.c:340:ContextThread() Authorized PC/SC client
00000005 [140542223648512] winscard_svc.c:344:ContextThread() Thread is started: dwClientID=14, threadContext @0x563b27d8ac10
00000011 [140542223648512] winscard_svc.c:362:ContextThread() Received command: CMD_VERSION from client 14
00000006 [140542223648512] winscard_svc.c:374:ContextThread() Client is protocol version 4:4
00000058 [140542223648512] winscard_svc.c:394:ContextThread() CMD_VERSION rv=0x0 for client 14
00000027 [140542223648512] winscard_svc.c:362:ContextThread() Received command: ESTABLISH_CONTEXT from client 14
00000006 [140542223648512] winscard.c:215:SCardEstablishContext() Establishing Context: 0x2EDC9306
00000004 [140542223648512] winscard_svc.c:459:ContextThread() ESTABLISH_CONTEXT rv=0x0 for client 14
00000045 [140542223648512] winscard_svc.c:362:ContextThread() Received command: CMD_GET_READERS_STATE from client 14
00000020 [140542223648512] winscard_svc.c:362:ContextThread() Received command: CMD_GET_READERS_STATE from client 14
00000059 [140542259574720] winscard_msg_srv.c:255:ProcessEventsServer() Common channel packet arrival
00000008 [140542259574720] winscard_msg_srv.c:267:ProcessEventsServer() ProcessCommonChannelRequest detects: 15
00000003 [140542259574720] pcscdaemon.c:133:SVCServiceRunLoop() A new context thread creation is requested: 15
00000034 [140542215255808] winscard_svc.c:340:ContextThread() Authorized PC/SC client
00000003 [140542215255808] winscard_svc.c:344:ContextThread() Thread is started: dwClientID=15, threadContext @0x563b27d8ad80
00000006 [140542215255808] winscard_svc.c:362:ContextThread() Received command: CMD_VERSION from client 15
00000007 [140542215255808] winscard_svc.c:374:ContextThread() Client is protocol version 4:4
00000004 [140542215255808] winscard_svc.c:394:ContextThread() CMD_VERSION rv=0x0 for client 15
00000017 [140542215255808] winscard_svc.c:362:ContextThread() Received command: ESTABLISH_CONTEXT from client 15
00000006 [140542215255808] winscard.c:215:SCardEstablishContext() Establishing Context: 0x38DF8D2F
00000005 [140542215255808] winscard_svc.c:459:ContextThread() ESTABLISH_CONTEXT rv=0x0 for client 15
00000055 [140542215255808] winscard_svc.c:362:ContextThread() Received command: CONNECT from client 15
00000005 [140542215255808] winscard_svc.c:497:ContextThread() Authorized client for 'ACS ACR122U 00 00'
00000004 [140542215255808] winscard.c:259:SCardConnect() Attempting Connect to ACS ACR122U 00 00 using protocol: 3
00000005 [140542215255808] readerfactory.c:821:RFReaderInfo() RefReader() count was: 1
00000003 [140542215255808] winscard.c:352:SCardConnect() powerState: POWER_STATE_IN_USE
00000002 [140542215255808] prothandler.c:108:PHSetProtocol() Attempting PTS to T=1
00000006 [140542215255808] ifdhandler.c:845:IFDHSetProtocolParameters() protocol T=1, usb:072f/2200:libudev:0:/dev/bus/usb/003/005 (lun: 0)
00000004 [140542215255808] ifdhandler.c:859:IFDHSetProtocolParameters() Timeout: 3000 ms
00000004 [140542215255808] winscard.c:431:SCardConnect() Active Protocol: T=1
00000004 [140542215255808] winscard.c:456:SCardConnect() hCard Identity: 74ea02aa
00000011 [140542215255808] winscard.c:518:SCardConnect() UnrefReader() count was: 2
00000005 [140542215255808] winscard_svc.c:511:ContextThread() CONNECT rv=0x0 for client 15
00000115 [140542215255808] winscard_svc.c:362:ContextThread() Received command: TRANSMIT from client 15
00000008 [140542215255808] readerfactory.c:848:RFReaderInfoById() RefReader() count was: 1
00000004 [140542215255808] winscard.c:1646:SCardTransmit() UnrefReader() count was: 2
00000004 [140542215255808] winscard_svc.c:683:ContextThread() TRANSMIT rv=0x8010000F for client 15
00002881 [140542215255808] winscard_svc.c:362:ContextThread() Received command: DISCONNECT from client 15
00000014 [140542215255808] readerfactory.c:848:RFReaderInfoById() RefReader() count was: 1
00000004 [140542215255808] winscard.c:884:SCardDisconnect() Active Contexts: 1
00000004 [140542215255808] winscard.c:885:SCardDisconnect() dwDisposition: 2
00000469 [140542215255808] ifdhandler.c:1387:IFDHPowerICC() action: PowerDown, usb:072f/2200:libudev:0:/dev/bus/usb/003/005 (lun: 0)
00000009 [140542215255808] -> 000000 63 00 00 00 00 00 0A 00 00 00 
00000400 [140542215255808] <- 000000 81 00 00 00 00 00 0A 00 81 00 
00000004 [140542215255808] winscard.c:907:SCardDisconnect() powerState: POWER_STATE_UNPOWERED
00000005 [140542215255808] ifdhandler.c:510:IFDHGetCapabilities() tag: 0xFB2, usb:072f/2200:libudev:0:/dev/bus/usb/003/005 (lun: 0)
00000004 [140542215255808] winscard.c:1033:SCardDisconnect() Stopping polling thread
00000004 [140542215255808] ifdhandler.c:475:IFDHStopPolling() usb:072f/2200:libudev:0:/dev/bus/usb/003/005 (lun: 0)
00001956 [140542215255808] winscard.c:1046:SCardDisconnect() UnrefReader() count was: 2
00000010 [140542240433920] ccid_usb.c:1848:InterruptRead() InterruptRead (3/5): 3
00000001 [140542215255808] winscard_svc.c:548:ContextThread() DISCONNECT rv=0x0 for client 15
00000060 [140542215255808] winscard_svc.c:362:ContextThread() Received command: RELEASE_CONTEXT from client 15
00000008 [140542215255808] winscard.c:229:SCardReleaseContext() Releasing Context: 0x38DF8D2F
00000011 [140542215255808] winscard_svc.c:474:ContextThread() RELEASE_CONTEXT rv=0x0 for client 15
00000024 [140542215255808] winscard_svc.c:354:ContextThread() Client die: 15
00000013 [140542215255808] winscard_svc.c:1057:MSGCleanupClient() Thread is stopping: dwClientID=15, threadContext @0x563b27d8ad80
00000002 [140542215255808] winscard_svc.c:1063:MSGCleanupClient() Freeing SCONTEXT @0x563b27d8ad80
00003292 [140542223648512] winscard_svc.c:354:ContextThread() Client die: 14
00000028 [140542223648512] winscard.c:229:SCardReleaseContext() Releasing Context: 0x2EDC9306
00000011 [140542223648512] winscard_svc.c:1057:MSGCleanupClient() Thread is stopping: dwClientID=14, threadContext @0x563b27d8ac10
00000003 [140542223648512] winscard_svc.c:1063:MSGCleanupClient() Freeing SCONTEXT @0x563b27d8ac10

@godfreychung
Copy link
Contributor 

00000004 [140542215255808] winscard.c:259:SCardConnect() Attempting Connect to ACS ACR122U 00 00 using protocol: 3
00000005 [140542215255808] readerfactory.c:821:RFReaderInfo() RefReader() count was: 1
00000003 [140542215255808] winscard.c:352:SCardConnect() powerState: POWER_STATE_IN_USE
00000002 [140542215255808] prothandler.c:108:PHSetProtocol() Attempting PTS to T=1
00000006 [140542215255808] ifdhandler.c:845:IFDHSetProtocolParameters() protocol T=1, usb:072f/2200:libudev:0:/dev/bus/usb/003/005 (lun: 0)
00000004 [140542215255808] ifdhandler.c:859:IFDHSetProtocolParameters() Timeout: 3000 ms
00000004 [140542215255808] winscard.c:431:SCardConnect() Active Protocol: T=1
00000004 [140542215255808] winscard.c:456:SCardConnect() hCard Identity: 74ea02aa
00000011 [140542215255808] winscard.c:518:SCardConnect() UnrefReader() count was: 2
00000005 [140542215255808] winscard_svc.c:511:ContextThread() CONNECT rv=0x0 for client 15
00000115 [140542215255808] winscard_svc.c:362:ContextThread() Received command: TRANSMIT from client 15
00000008 [140542215255808] readerfactory.c:848:RFReaderInfoById() RefReader() count was: 1
00000004 [140542215255808] winscard.c:1646:SCardTransmit() UnrefReader() count was: 2
00000004 [140542215255808] winscard_svc.c:683:ContextThread() TRANSMIT rv=0x8010000F for client 15
00002881 [140542215255808] winscard_svc.c:362:ContextThread() Received command: DISCONNECT from client 15

According to the log, your script uses SCARD_PROTOCOL_T0 | SCARD_PROTOCOL_T1 (using protocol: 3) for card connection.

According to the ATR, It will choose T=1 for the highest protocol.
http://smartcard-atr.appspot.com/parse?ATR=3B8F8001804F0CA000000306030001000000006A

The active protocol is T=1. If your script passes T=0 to SCardTransmit(), it will return protocol mismatch error (0x8010000F).

osmocom-gerrit pushed a commit to osmocom/pysim that referenced this issue Mar 1, 2020
@axilirator
transport/pcsc: explicitly specify T0 protocol
fa617ac 
From pyscard user's guide [1]:

   == Selecting the card communication protocol ==

   By defaults, the connect() method of the CardConnection object
   will try to connect using either the T=0 or T=1 protocol.
   To force a connection protocol, you can pass the required
   protocol to the connect() method.

This means that a PC/SC ifd handler may automatically choose T=1
as the highest protocol if the card indicates both in its ATR [2].

Since pySim only supports T=0, let's select it explicitly.

[1] https://pyscard.sourceforge.io/user-guide.html
[2] acshk/acsccid#16 (comment)

Change-Id: Ifed4574aab98a86c3ebbeb191f36a8282103e775
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@roaldnefs @godfreychung