LudovicRousseau / PCSC

pcsc-lite: PC/SC implementation
https://pcsclite.apdu.fr/
Other
259 stars 107 forks source link

Gemalto IDBrigde CT40 on some Linux #71

Closed antonio-fr closed 4 years ago

antonio-fr commented 4 years ago

I'm using a professional USB card reader Gemalto IDBrigde CT40 for smartcard development. I'm facing some issues with some Linux (Debian/Ubuntu). After deepdown, the issue always happens after a particular command. Still this command is not particular from others : 8010000041[65BPubKey], response is 48 bytes long. Any following command leads to :"smartcard.Exceptions.CardConnectionException: Failed to transmit with protocol T1. Transaction failed."

The logs are the following at the error, when the host try to send the next command :

Dec  2 22:06:28 raspberrypi pcscd[3615]: 00000000 ccid_usb.c:859:WriteUSB() write failed (1/22): -7 LIBUSB_ERROR_TIMEOUT
Dec  2 22:06:28 raspberrypi pcscd[3615]: 00000143 openct/proto-t1.c:215:t1_transceive() fatal: transmit/receive failed
Dec  2 22:06:28 raspberrypi pcscd[3615]: 00000037 ifdwrapper.c:543:IFDTransmit() Card not transacted: 612
Dec  2 22:06:28 raspberrypi pcscd[3615]: 00000031 winscard.c:1626:SCardTransmit() Card not transacted: 0x80100016

In an other log file

00000039 winscard.c:1601:SCardTransmit() Send Protocol: T=1
00000036 ifdhandler.c:1303:IFDHTransmitToICC() usb:08e6/3437:libudev:0:/dev/bus/usb/001/024 (lun: 0)
05000390 ccid_usb.c:859:WriteUSB() write failed (1/24): -7 LIBUSB_ERROR_TIMEOUT
00000166 openct/proto-t1.c:215:t1_transceive() fatal: transmit/receive failed
00000052 ifdwrapper.c:543:IFDTransmit() Card not transacted: 612
00000044 winscard.c:1626:SCardTransmit() Card not transacted: 0x80100016

LibUSB version 1.0.22 CCID driver version 1.4.30 pcscd 1.8.24 pcsc-lite version 1.8.24

pcsc-lite version 1.8.24.
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

Operating system Raspbian Linux raspberrypi 4.19.75

Hardware details : Raspberry Pi 2 B 1.1

Smart card reader manufacturer name and reader model name Gemalto IDBrigde CT40 I believe the issue is in this reader : Even if I remove-insert a smartcard, it is not recognized in the system, I can't reconnect to any card. I have to unplug and plug the USB plug of the reader to make it work again.

Smart card name : NXP P71 J3R200

This seems to happen only with this reader. And also with this reader, on other platforms such as PC x64 with Ubuntu 18.04/19.04, the issue also happens. In Windows, this is OK.

Full Log

00000000 debuglog.c:299:DebugLogSetLevel() debug level=debug
00000150 debuglog.c:320:DebugLogSetCategory() Debug options: APDU
00000022 [1995993136] pcscdaemon.c:352:main() Force colored logs
00000248 [1995993136] utils.c:82:GetDaemonPid() Can't open /var/run/pcscd/pcscd.pid: No such file or directory
00000695 [1995993136] configfile.l:284:DBGetReaderListDir() Parsing conf directory: /etc/reader.conf.d
00000130 [1995993136] configfile.l:321:DBGetReaderListDir() Skipping non regular file: .
00000023 [1995993136] configfile.l:321:DBGetReaderListDir() Skipping non regular file: ..
00000021 [1995993136] configfile.l:360:DBGetReaderList() Parsing conf file: /etc/reader.conf.d/libccidtwin
00000246 [1995993136] pcscdaemon.c:662:main() pcsc-lite 1.8.24 daemon ready.
00019281 [1995993136] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/001/001
00001354 [1995993136] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/001/001
00001251 [1995993136] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x0424, PID: 0x9514, path: /dev/bus/usb/001/002
00001270 [1995993136] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x0424, PID: 0xEC00, path: /dev/bus/usb/001/003
00001176 [1995993136] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x0424, PID: 0x9514, path: /dev/bus/usb/001/002
00001169 [1995993136] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x08E6, PID: 0x3437, path: /dev/bus/usb/001/026
00000053 [1995993136] hotplug_libudev.c:436:HPAddDevice() Adding USB device: Gemalto PC Twin Reader
00000381 [1995993136] readerfactory.c:1075:RFInitializeReader() Attempting startup of Gemalto PC Twin Reader (77803048) 00 00 using /usr/lib/pcsc/drivers/ifd-ccid.bundle/Contents/Linux/libccid.so
00001466 [1995993136] readerfactory.c:950:RFBindFunctions() Loading IFD Handler 3.0
00000181 [1995993136] ifdhandler.c:1961:init_driver() Driver version: 1.4.30
00005124 [1995993136] ifdhandler.c:1978:init_driver() LogLevel: 0x0003
00000051 [1995993136] ifdhandler.c:1989:init_driver() DriverOptions: 0x0000
00001218 [1995993136] ifdhandler.c:2002:init_driver() LogLevel from LIBCCID_ifdLogLevel: 0x000F
00000034 [1995993136] ifdhandler.c:110:CreateChannelByNameOrChannel() Lun: 0, device: usb:08e6/3437:libudev:0:/dev/bus/usb/001/026
00000028 [1995993136] ccid_usb.c:237:OpenUSBByName() Reader index: 0, Device: usb:08e6/3437:libudev:0:/dev/bus/usb/001/026
00000054 [1995993136] ccid_usb.c:269:OpenUSBByName() interface_number: 0
00000019 [1995993136] ccid_usb.c:270:OpenUSBByName() usb bus/device: 1/26
00000018 [1995993136] ccid_usb.c:302:OpenUSBByName() Using: /usr/lib/pcsc/drivers/ifd-ccid.bundle/Contents/Info.plist
00005104 [1995993136] ccid_usb.c:320:OpenUSBByName() ifdManufacturerString: Ludovic Rousseau (ludovic.rousseau@free.fr)
00000041 [1995993136] ccid_usb.c:321:OpenUSBByName() ifdProductString: Generic CCID driver
00000021 [1995993136] 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.
00014760 [1995993136] ccid_usb.c:406:OpenUSBByName() Try device: 1/26
00000050 [1995993136] ccid_usb.c:416:OpenUSBByName() vid/pid : 08E6/3437
00000020 [1995993136] ccid_usb.c:483:OpenUSBByName() Checking device: 1/26
00000022 [1995993136] ccid_usb.c:554:OpenUSBByName() Trying to open USB bus/device: 1/26
00087376 [1995993136] ccid_usb.c:660:OpenUSBByName() Found Vendor/Product: 08E6/3437 (Gemalto PC Twin Reader)
00000062 [1995993136] ccid_usb.c:662:OpenUSBByName() Using USB bus/device: 1/26
00000024 [1995993136] ccid_usb.c:1253:ControlUSB() request: 0x03
00004193 [1995993136] receive: 67 32 00 00 CE 64 00 00 9D C9 00 00 3A 93 01 00 74 26 03 00 E7 4C 06 00 CE 99 0C 00 D7 5C 02 00 11 F0 03 00 34 43 00 00 69 86 00 00 D1 0C 01 00 A2 19 02 00 45 33 04 00 8A 66 08 00 0B A0 02 00 E6 60 00 00 CC C1 00 00 99 83 01 00 32 07 03 00 63 0E 06 00 B3 22 01 00 7F E4 01 00 06 50 01 00 36 97 00 00 04 FC 00 00 A5 50 00 00 4A A1 00 00 95 42 01 00 29 85 02 00 F8 78 00 00 3E 49 00 00 7C 92 00 00 F8 24 01 00 F0 49 02 00 E0 93 04 00 C0 27 09 00 74 B7 01 00 6C DC 02 00 A8 61 00 00 50 C3 00 00 A0 86 01 00 40 0D 03 00 80 1A 06 00 48 E8 01 00 BA DB 00 00 36 6E 01 00 24 F4 00 00 DD 6D 00 00 1B B7 00 00 
00000090 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 12903 bps
00000021 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 25806 bps
00000015 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 51613 bps
00000014 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 103226 bps
00000014 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 206452 bps
00000014 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 412903 bps
00000013 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 825806 bps
00000013 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 154839 bps
00000013 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 258065 bps
00000021 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 17204 bps
00000029 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 34409 bps
00000015 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 68817 bps
00000014 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 137634 bps
00000013 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 275269 bps
00000013 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 550538 bps
00000013 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 172043 bps
00000014 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 24806 bps
00000012 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 49612 bps
00000014 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 99225 bps
00000013 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 198450 bps
00000013 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 396899 bps
00000013 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 74419 bps
00000013 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 124031 bps
00000014 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 86022 bps
00000013 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 38710 bps
00000013 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 64516 bps
00000013 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 20645 bps
00000013 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 41290 bps
00000013 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 82581 bps
00000013 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 165161 bps
00000013 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 30968 bps
00000013 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 18750 bps
00000014 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 37500 bps
00000013 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 75000 bps
00000013 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 150000 bps
00000013 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 300000 bps
00000013 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 600000 bps
00000022 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 112500 bps
00000013 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 187500 bps
00000014 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 25000 bps
00000013 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 50000 bps
00000013 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 100000 bps
00000014 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 200000 bps
00000013 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 400000 bps
00000013 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 125000 bps
00000013 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 56250 bps
00000014 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 93750 bps
00000013 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 62500 bps
00000013 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 28125 bps
00000013 [1995993136] ccid_usb.c:1233:get_data_rates() declared: 46875 bps
00013791 [1995993136] ccid_usb.c:1306:InterruptRead() before (0)
00000980 [1995993136] ccid_usb.c:1352:InterruptRead() after (0) (0)
00000046 [1995993136] NotifySlotChange: 50 03 
00000032 [1995993136] -> 000000 65 00 00 00 00 00 00 00 00 00 
00001424 [1995993136] <- 000000 81 00 00 00 00 00 00 01 00 00 
00000080 [1995993136] -> 000000 65 00 00 00 00 00 01 00 00 00 
00000659 [1995993136] <- 000000 81 00 00 00 00 00 01 01 00 00 
00000168 [1995993136] -> 000000 6B 01 00 00 00 00 02 00 00 00 6A 
00001797 [1995993136] <- 000000 83 00 00 00 00 00 02 41 0A 00 
00000038 [1995993136] commands.c:1004:CmdEscapeCheck error on byte 10
00000022 [1995993136] ccid.c:240:set_gemalto_firmware_features() GET_FIRMWARE_FEATURES failed: 612, len=0
00000022 [1995993136] ifdhandler.c:381:IFDHGetCapabilities() tag: 0xFB3, usb:08e6/3437:libudev:0:/dev/bus/usb/001/026 (lun: 0)
00000017 [1995993136] readerfactory.c:396:RFAddReader() Using the reader polling thread
00000016 [1995993136] ifdhandler.c:1821:IFDHICCPresence() usb:08e6/3437:libudev:0:/dev/bus/usb/001/026 (lun: 0)
00000030 [1995993136] -> 000000 65 00 00 00 00 00 03 00 00 00 
00000972 [1995993136] <- 000000 81 00 00 00 00 00 03 01 00 00 
00000032 [1995993136] ifdhandler.c:1942:IFDHICCPresence() Card present
00000457 [1995993136] ifdhandler.c:381:IFDHGetCapabilities() tag: 0xFAE, usb:08e6/3437:libudev:0:/dev/bus/usb/001/026 (lun: 0)
00000040 [1995993136] ifdhandler.c:476:IFDHGetCapabilities() Reader supports 1 slot(s)
00000153 [1974522864] ifdhandler.c:1821:IFDHICCPresence() usb:08e6/3437:libudev:0:/dev/bus/usb/001/026 (lun: 0)
00000048 [1974522864] -> 000000 65 00 00 00 00 00 04 00 00 00 
00002248 [1974522864] <- 000000 81 00 00 00 00 00 04 01 00 00 
00000049 [1974522864] ifdhandler.c:1942:IFDHICCPresence() Card present
00000031 [1974522864] ifdhandler.c:1821:IFDHICCPresence() usb:08e6/3437:libudev:0:/dev/bus/usb/001/026 (lun: 0)
00000029 [1974522864] -> 000000 65 00 00 00 00 00 05 00 00 00 
00000636 [1995993136] hotplug_libudev.c:297:get_driver() Looking for a driver for VID: 0x0424, PID: 0x9514, path: /dev/bus/usb/001/002
00000952 [1995993136] readerfactory.c:1410:RFWaitForReaderInit() Waiting init for reader: Gemalto PC Twin Reader (77803048) 00 00
00000236 [1974522864] <- 000000 81 00 00 00 00 00 05 01 00 00 
00000030 [1974522864] ifdhandler.c:1942:IFDHICCPresence() Card present
00000022 [1974522864] ifdhandler.c:1154:IFDHPowerICC() action: PowerUp, usb:08e6/3437:libudev:0:/dev/bus/usb/001/026 (lun: 0)
00000031 [1974522864] -> 000000 62 00 00 00 00 00 06 01 00 00 
00009823 [1995993136] readerfactory.c:1410:RFWaitForReaderInit() Waiting init for reader: Gemalto PC Twin Reader (77803048) 00 00
00010132 [1995993136] readerfactory.c:1410:RFWaitForReaderInit() Waiting init for reader: Gemalto PC Twin Reader (77803048) 00 00
00010123 [1995993136] readerfactory.c:1410:RFWaitForReaderInit() Waiting init for reader: Gemalto PC Twin Reader (77803048) 00 00
00010124 [1995993136] readerfactory.c:1410:RFWaitForReaderInit() Waiting init for reader: Gemalto PC Twin Reader (77803048) 00 00
00010124 [1995993136] readerfactory.c:1410:RFWaitForReaderInit() Waiting init for reader: Gemalto PC Twin Reader (77803048) 00 00
00010126 [1995993136] readerfactory.c:1410:RFWaitForReaderInit() Waiting init for reader: Gemalto PC Twin Reader (77803048) 00 00
00003989 [1974522864] <- 000000 80 14 00 00 00 00 06 00 00 00 3B FA 18 00 00 81 31 FE 45 4A 54 61 78 43 6F 72 65 56 31 B2 
00000037 [1974522864] eventhandler.c:289:EHStatusHandlerThread() powerState: POWER_STATE_POWERED
00000041 [1974522864] Card ATR: 3B FA 18 00 00 81 31 FE 45 4A 54 61 78 43 6F 72 65 56 31 B2 
00000025 [1974522864] ifdhandler.c:1821:IFDHICCPresence() usb:08e6/3437:libudev:0:/dev/bus/usb/001/026 (lun: 0)
00000028 [1974522864] -> 000000 65 00 00 00 00 00 07 00 00 00 
00001830 [1974522864] <- 000000 81 00 00 00 00 00 07 00 00 00 
00000033 [1974522864] ifdhandler.c:1942:IFDHICCPresence() Card present
00000019 [1974522864] ifdhandler.c:310:IFDHPolling() usb:08e6/3437:libudev:0:/dev/bus/usb/001/026 (lun: 0) 5000 ms
00000016 [1974522864] ccid_usb.c:1306:InterruptRead() before (0)
05000284 [1974522864] ccid_usb.c:1352:InterruptRead() after (0) (2)
00000081 [1974522864] ifdhandler.c:1821:IFDHICCPresence() usb:08e6/3437:libudev:0:/dev/bus/usb/001/026 (lun: 0)
00000062 [1974522864] -> 000000 65 00 00 00 00 00 08 00 00 00 
00001533 [1974522864] <- 000000 81 00 00 00 00 00 08 00 00 00 
00000057 [1974522864] ifdhandler.c:1942:IFDHICCPresence() Card present
00000035 [1974522864] ifdhandler.c:1154:IFDHPowerICC() action: PowerDown, usb:08e6/3437:libudev:0:/dev/bus/usb/001/026 (lun: 0)
00000042 [1974522864] -> 000000 63 00 00 00 00 00 09 00 00 00 
00010004 [1974522864] <- 000000 81 00 00 00 00 00 09 01 00 00 
00000049 [1974522864] eventhandler.c:482:EHStatusHandlerThread() powerState: POWER_STATE_UNPOWERED
00000031 [1974522864] ifdhandler.c:1821:IFDHICCPresence() usb:08e6/3437:libudev:0:/dev/bus/usb/001/026 (lun: 0)
00000040 [1974522864] -> 000000 65 00 00 00 00 00 0A 00 00 00 
00001238 [1974522864] <- 000000 81 00 00 00 00 00 0A 01 00 00 
00000043 [1974522864] ifdhandler.c:1942:IFDHICCPresence() Card present
00000029 [1974522864] ifdhandler.c:310:IFDHPolling() usb:08e6/3437:libudev:0:/dev/bus/usb/001/026 (lun: 0) 600000 ms
00000027 [1974522864] ccid_usb.c:1306:InterruptRead() before (0)
26908889 [1995993136] winscard_msg_srv.c:255:ProcessEventsServer() Common channel packet arrival
00000116 [1995993136] winscard_msg_srv.c:267:ProcessEventsServer() ProcessCommonChannelRequest detects: 14
00000029 [1995993136] pcscdaemon.c:133:SVCServiceRunLoop() A new context thread creation is requested: 14
00000439 [1954542576] winscard_svc.c:340:ContextThread() Authorized PC/SC client
00000175 [1954542576] winscard_svc.c:344:ContextThread() Thread is started: dwClientID=14, threadContext @0x5b51c8
00000142 [1954542576] winscard_svc.c:362:ContextThread() Received command: CMD_VERSION from client 14
00000119 [1954542576] winscard_svc.c:374:ContextThread() Client is protocol version 4:4
00000088 [1954542576] winscard_svc.c:394:ContextThread() CMD_VERSION rv=0x0 for client 14
00000330 [1954542576] winscard_svc.c:362:ContextThread() Received command: ESTABLISH_CONTEXT from client 14
00000211 [1954542576] winscard.c:215:SCardEstablishContext() Establishing Context: 0x2414E60F
00000123 [1954542576] winscard_svc.c:459:ContextThread() ESTABLISH_CONTEXT rv=0x0 for client 14
00000494 [1954542576] winscard_svc.c:362:ContextThread() Received command: CMD_GET_READERS_STATE from client 14
00000298 [1954542576] winscard_svc.c:362:ContextThread() Received command: CMD_GET_READERS_STATE from client 14
00000708 [1995993136] winscard_msg_srv.c:255:ProcessEventsServer() Common channel packet arrival
00000103 [1995993136] winscard_msg_srv.c:267:ProcessEventsServer() ProcessCommonChannelRequest detects: 15
00000172 [1995993136] pcscdaemon.c:133:SVCServiceRunLoop() A new context thread creation is requested: 15
00000418 [1946149872] winscard_svc.c:340:ContextThread() Authorized PC/SC client
00000045 [1946149872] winscard_svc.c:344:ContextThread() Thread is started: dwClientID=15, threadContext @0x5a6bc8
00000061 [1946149872] winscard_svc.c:362:ContextThread() Received command: CMD_VERSION from client 15
00000037 [1946149872] winscard_svc.c:374:ContextThread() Client is protocol version 4:4
00000020 [1946149872] winscard_svc.c:394:ContextThread() CMD_VERSION rv=0x0 for client 15
00000230 [1946149872] winscard_svc.c:362:ContextThread() Received command: ESTABLISH_CONTEXT from client 15
00000049 [1946149872] winscard.c:215:SCardEstablishContext() Establishing Context: 0x41BFA0B9
00000019 [1946149872] winscard_svc.c:459:ContextThread() ESTABLISH_CONTEXT rv=0x0 for client 15
00000629 [1946149872] winscard_svc.c:362:ContextThread() Received command: CONNECT from client 15
00000054 [1946149872] winscard_svc.c:497:ContextThread() Authorized client for 'Gemalto PC Twin Reader (77803048) 00 00'
00000019 [1946149872] winscard.c:259:SCardConnect() Attempting Connect to Gemalto PC Twin Reader (77803048) 00 00 using protocol: 2
00000018 [1946149872] readerfactory.c:821:RFReaderInfo() RefReader() count was: 1
00000023 [1946149872] ifdhandler.c:1821:IFDHICCPresence() usb:08e6/3437:libudev:0:/dev/bus/usb/001/026 (lun: 0)
00000037 [1946149872] -> 000000 65 00 00 00 00 00 0B 00 00 00 
00001024 [1946149872] <- 000000 81 00 00 00 00 00 0B 01 00 00 
00000039 [1946149872] ifdhandler.c:1942:IFDHICCPresence() Card present
00000025 [1946149872] ifdhandler.c:1154:IFDHPowerICC() action: PowerUp, usb:08e6/3437:libudev:0:/dev/bus/usb/001/026 (lun: 0)
00000030 [1946149872] -> 000000 62 00 00 00 00 00 0C 01 00 00 
00063339 [1946149872] <- 000000 80 14 00 00 00 00 0C 00 00 00 3B FA 18 00 00 81 31 FE 45 4A 54 61 78 43 6F 72 65 56 31 B2 
00000046 [1946149872] winscard.c:332:SCardConnect() power up complete.
00000035 [1946149872] Card ATR: 3B FA 18 00 00 81 31 FE 45 4A 54 61 78 43 6F 72 65 56 31 B2 
00000015 [1946149872] winscard.c:352:SCardConnect() powerState: POWER_STATE_IN_USE
00000018 [1946149872] prothandler.c:108:PHSetProtocol() Attempting PTS to T=1
00000019 [1946149872] ifdhandler.c:695:IFDHSetProtocolParameters() protocol T=1, usb:08e6/3437:libudev:0:/dev/bus/usb/001/026 (lun: 0)
00000022 [1946149872] ifdhandler.c:2036:find_baud_rate() Card baud rate: 154838
00000017 [1946149872] ifdhandler.c:2045:find_baud_rate() Reader can do: 12903
00000014 [1946149872] ifdhandler.c:2045:find_baud_rate() Reader can do: 25806
00000013 [1946149872] ifdhandler.c:2045:find_baud_rate() Reader can do: 51613
00000014 [1946149872] ifdhandler.c:2045:find_baud_rate() Reader can do: 103226
00000013 [1946149872] ifdhandler.c:2045:find_baud_rate() Reader can do: 206452
00000013 [1946149872] ifdhandler.c:2045:find_baud_rate() Reader can do: 412903
00000013 [1946149872] ifdhandler.c:2045:find_baud_rate() Reader can do: 825806
00000013 [1946149872] ifdhandler.c:2045:find_baud_rate() Reader can do: 154839
00000014 [1946149872] ifdhandler.c:818:IFDHSetProtocolParameters() Set speed to 154838 bauds
00000015 [1946149872] towitoko/atr.c:334:ATR_GetDefaultProtocol() T=1 Protocol Found
00000014 [1946149872] towitoko/atr.c:342:ATR_GetDefaultProtocol() default protocol: T=1
00000013 [1946149872] towitoko/atr.c:334:ATR_GetDefaultProtocol() T=1 Protocol Found
00000019 [1946149872] PPS: Sending request: FF 11 18 F6 
00000032 [1946149872] -> 000000 6F 04 00 00 00 00 0D 00 00 00 FF 11 18 F6 
00020025 [1946149872] <- 000000 80 04 00 00 00 00 0D 00 00 00 FF 11 18 F6 
00000047 [1946149872] PPS: Receiving confirm: FF 11 18 F6 
00000027 [1946149872] ifdhandler.c:979:IFDHSetProtocolParameters() BWI/CWI (TB3) present: 0x45
00000022 [1946149872] ifdhandler.c:1013:IFDHSetProtocolParameters() IFSC (TA3) present: 254
00000015 [1946149872] ifdhandler.c:1017:IFDHSetProtocolParameters() Timeout: 2282 ms
00000016 [1946149872] commands.c:2254:SetParameters() length: 7 bytes
00000034 [1946149872] -> 000000 61 07 00 00 00 00 0E 01 00 00 18 10 00 45 00 FE 00 
00000898 [1946149872] <- 000000 82 07 00 00 00 00 0E 00 00 01 18 10 00 45 00 FE 00 
00000034 [1946149872] ifdhandler.c:1074:IFDHSetProtocolParameters() IFSC (TA3) present: 254
00000017 [1946149872] ifdhandler.c:1081:IFDHSetProtocolParameters() Negotiate IFSD at 254
00000022 [1946149872] sending: 00 C1 01 FE 3E 
00000033 [1946149872] -> 000000 6F 05 00 00 00 00 0F 00 00 00 00 C1 01 FE 3E 
00003327 [1946149872] <- 000000 80 05 00 00 00 00 0F 00 00 00 00 E1 01 FE 1E 
00000038 [1946149872] received: 00 E1 01 FE 1E 
00000024 [1946149872] ifdhandler.c:1087:IFDHSetProtocolParameters() T=1: IFSC=254, IFSD=254
00000019 [1946149872] winscard.c:431:SCardConnect() Active Protocol: T=1
00000023 [1946149872] winscard.c:456:SCardConnect() hCard Identity: 3640c96e
00000024 [1946149872] winscard.c:518:SCardConnect() UnrefReader() count was: 2
00000025 [1946149872] winscard_svc.c:511:ContextThread() CONNECT rv=0x0 for client 15
00001822 [1946149872] winscard_svc.c:362:ContextThread() Received command: TRANSMIT from client 15
00000168 [1946149872] readerfactory.c:848:RFReaderInfoById() RefReader() count was: 1
00000026 [1946149872] winscard.c:1601:SCardTransmit() Send Protocol: T=1
00000037 [1946149872] APDU: 00 A4 04 00 07 A0 00 00 10 00 01 01 
00000022 [1946149872] ifdhandler.c:1303:IFDHTransmitToICC() usb:08e6/3437:libudev:0:/dev/bus/usb/001/026 (lun: 0)
00000019 [1946149872] commands.c:2228:CmdXfrBlockTPDU_T1() T=1: 12 and 65548 bytes
00000018 [1946149872] openct/proto-t1.c:580:t1_build() more bit: 0
00000033 [1946149872] sending: 00 00 0C 00 A4 04 00 07 A0 00 00 10 00 01 01 1B 
00000047 [1946149872] -> 000000 6F 10 00 00 00 00 10 00 00 00 00 00 0C 00 A4 04 00 07 A0 00 00 10 00 01 01 1B 
00075858 [1946149872] <- 000000 80 2A 00 00 00 00 10 00 00 00 00 00 26 50 00 08 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 90 00 EE 
00000089 [1946149872] received: 00 00 26 50 00 08 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 90 00 EE 
00000022 [1946149872] openct/proto-t1.c:356:t1_transceive() 
00000099 [1946149872] SW: 50 00 08 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 90 00 
00000022 [1946149872] winscard.c:1646:SCardTransmit() UnrefReader() count was: 2
00000020 [1946149872] winscard_svc.c:683:ContextThread() TRANSMIT rv=0x0 for client 15
00000747 [1946149872] winscard_svc.c:362:ContextThread() Received command: TRANSMIT from client 15
00000172 [1946149872] readerfactory.c:848:RFReaderInfoById() RefReader() count was: 1
00000028 [1946149872] winscard.c:1601:SCardTransmit() Send Protocol: T=1
00000031 [1946149872] APDU: 80 FE 00 00 01 01 
00000021 [1946149872] ifdhandler.c:1303:IFDHTransmitToICC() usb:08e6/3437:libudev:0:/dev/bus/usb/001/026 (lun: 0)
00000018 [1946149872] commands.c:2228:CmdXfrBlockTPDU_T1() T=1: 6 and 65548 bytes
00000018 [1946149872] openct/proto-t1.c:580:t1_build() more bit: 0
00000026 [1946149872] sending: 00 40 06 80 FE 00 00 01 01 38 
00000042 [1946149872] -> 000000 6F 0A 00 00 00 00 11 00 00 00 00 40 06 80 FE 00 00 01 01 38 
00008345 [1946149872] <- 000000 80 06 00 00 00 00 11 00 00 00 00 40 02 6A 80 A8 
00000045 [1946149872] received: 00 40 02 6A 80 A8 
00000021 [1946149872] openct/proto-t1.c:356:t1_transceive() 
00000020 [1946149872] SW: 6A 80 
00000017 [1946149872] winscard.c:1646:SCardTransmit() UnrefReader() count was: 2
00000018 [1946149872] winscard_svc.c:683:ContextThread() TRANSMIT rv=0x0 for client 15
00001477 [1946149872] winscard_svc.c:362:ContextThread() Received command: TRANSMIT from client 15
00000187 [1946149872] readerfactory.c:848:RFReaderInfoById() RefReader() count was: 1
00000071 [1946149872] winscard.c:1601:SCardTransmit() Send Protocol: T=1
00000038 [1946149872] APDU: 80 F8 00 00 08 37 8E DE CD 84 3B F4 E0 
00000020 [1946149872] ifdhandler.c:1303:IFDHTransmitToICC() usb:08e6/3437:libudev:0:/dev/bus/usb/001/026 (lun: 0)
00000019 [1946149872] commands.c:2228:CmdXfrBlockTPDU_T1() T=1: 13 and 65548 bytes
00000020 [1946149872] openct/proto-t1.c:580:t1_build() more bit: 0
00000036 [1946149872] sending: 00 00 0D 80 F8 00 00 08 37 8E DE CD 84 3B F4 E0 7C 
00000048 [1946149872] -> 000000 6F 11 00 00 00 00 12 00 00 00 00 00 0D 80 F8 00 00 08 37 8E DE CD 84 3B F4 E0 7C 
00058796 [1946149872] <- 000000 80 97 00 00 00 00 12 00 00 00 00 00 93 43 37 8E DE CD 84 3B F4 E0 04 79 11 C2 CD B2 11 68 53 16 8E 32 22 6A FF 03 B1 B1 67 9E 73 70 67 23 73 3F DA AB C6 1A 03 F1 1C 93 C6 82 3F 77 DD B1 4B A7 0B 8B 3D A5 92 19 2F 14 2A 80 9E 4A 96 68 11 47 A0 BA 1E 8E C9 D7 A1 30 45 02 20 53 B1 4C 5F 09 66 7B 7C FF 2D 38 A4 B7 FC 05 B5 E8 D7 1B 57 23 3B 55 4B 30 3F 6C 81 6C A7 FF 29 02 21 00 FA F1 78 37 86 16 1A B9 94 79 72 11 7F 77 38 FE D5 DC 4D 70 4F BB AD F6 BB 8B 3A 2C 87 B9 1A 6A 90 00 57 
00000203 [1946149872] received: 00 00 93 43 37 8E DE CD 84 3B F4 E0 04 79 11 C2 CD B2 11 68 53 16 8E 32 22 6A FF 03 B1 B1 67 9E 73 70 67 23 73 3F DA AB C6 1A 03 F1 1C 93 C6 82 3F 77 DD B1 4B A7 0B 8B 3D A5 92 19 2F 14 2A 80 9E 4A 96 68 11 47 A0 BA 1E 8E C9 D7 A1 30 45 02 20 53 B1 4C 5F 09 66 7B 7C FF 2D 38 A4 B7 FC 05 B5 E8 D7 1B 57 23 3B 55 4B 30 3F 6C 81 6C A7 FF 29 02 21 00 FA F1 78 37 86 16 1A B9 94 79 72 11 7F 77 38 FE D5 DC 4D 70 4F BB AD F6 BB 8B 3A 2C 87 B9 1A 6A 90 00 57 
00000167 [1946149872] openct/proto-t1.c:356:t1_transceive() 
00000177 [1946149872] SW: 43 37 8E DE CD 84 3B F4 E0 04 79 11 C2 CD B2 11 68 53 16 8E 32 22 6A FF 03 B1 B1 67 9E 73 70 67 23 73 3F DA AB C6 1A 03 F1 1C 93 C6 82 3F 77 DD B1 4B A7 0B 8B 3D A5 92 19 2F 14 2A 80 9E 4A 96 68 11 47 A0 BA 1E 8E C9 D7 A1 30 45 02 20 53 B1 4C 5F 09 66 7B 7C FF 2D 38 A4 B7 FC 05 B5 E8 D7 1B 57 23 3B 55 4B 30 3F 6C 81 6C A7 FF 29 02 21 00 FA F1 78 37 86 16 1A B9 94 79 72 11 7F 77 38 FE D5 DC 4D 70 4F BB AD F6 BB 8B 3A 2C 87 B9 1A 6A 90 00 
00000026 [1946149872] winscard.c:1646:SCardTransmit() UnrefReader() count was: 2
00000020 [1946149872] winscard_svc.c:683:ContextThread() TRANSMIT rv=0x0 for client 15
00000924 [1946149872] winscard_svc.c:362:ContextThread() Received command: TRANSMIT from client 15
00000165 [1946149872] readerfactory.c:848:RFReaderInfoById() RefReader() count was: 1
00000078 [1946149872] winscard.c:1601:SCardTransmit() Send Protocol: T=1
00000032 [1946149872] APDU: 80 F7 00 00 00 00 00 
00000020 [1946149872] ifdhandler.c:1303:IFDHTransmitToICC() usb:08e6/3437:libudev:0:/dev/bus/usb/001/026 (lun: 0)
00000019 [1946149872] commands.c:2228:CmdXfrBlockTPDU_T1() T=1: 7 and 65548 bytes
00000017 [1946149872] openct/proto-t1.c:580:t1_build() more bit: 0
00000030 [1946149872] sending: 00 40 07 80 F7 00 00 00 00 00 30 
00000043 [1946149872] -> 000000 6F 0B 00 00 00 00 13 00 00 00 00 40 07 80 F7 00 00 00 00 00 30 
00030261 [1946149872] <- 000000 80 02 01 00 00 00 13 00 00 00 00 60 FE 01 1D 30 82 01 19 30 81 C1 A0 03 02 01 02 02 09 00 A7 9C 07 DC 13 D4 F4 16 30 0A 06 08 2A 86 48 CE 3D 04 03 02 30 13 31 11 30 0F 06 03 55 04 03 13 08 43 72 79 70 74 6E 6F 78 30 1E 17 0D 31 38 31 32 30 39 30 37 30 34 35 38 5A 17 0D 32 32 31 32 30 38 30 37 30 34 35 38 5A 30 13 31 11 30 0F 06 03 55 04 03 13 08 43 72 79 70 74 6E 6F 78 30 59 30 13 06 07 2A 86 48 CE 3D 02 01 06 08 2A 86 48 CE 3D 03 01 07 03 42 00 04 83 12 E1 14 1B 91 55 B7 6A EC 56 28 0E 2C 46 96 AF D9 07 17 6B 43 53 D1 8A 9C ED F7 FB F3 7F 5C 30 42 A5 EB 94 A5 EC 52 7A 40 BC 9D 44 98 DF 7D 33 ED 7F 55 8D DC 6A 20 8A 24 5A 9E 97 5E 62 05 30 0A 06 08 2A 86 48 CE 3D 04 03 02 03 47 00 30 44 02 20 12 48 EF D8 46 88 1F F3 A7 AA F6 FF 87 7F 80 5B 79 B8 09 9D AD CD BB AD 68 48 AA 8E 12 8A E3 D9 02 F9 
00000320 [1946149872] received: 00 60 FE 01 1D 30 82 01 19 30 81 C1 A0 03 02 01 02 02 09 00 A7 9C 07 DC 13 D4 F4 16 30 0A 06 08 2A 86 48 CE 3D 04 03 02 30 13 31 11 30 0F 06 03 55 04 03 13 08 43 72 79 70 74 6E 6F 78 30 1E 17 0D 31 38 31 32 30 39 30 37 30 34 35 38 5A 17 0D 32 32 31 32 30 38 30 37 30 34 35 38 5A 30 13 31 11 30 0F 06 03 55 04 03 13 08 43 72 79 70 74 6E 6F 78 30 59 30 13 06 07 2A 86 48 CE 3D 02 01 06 08 2A 86 48 CE 3D 03 01 07 03 42 00 04 83 12 E1 14 1B 91 55 B7 6A EC 56 28 0E 2C 46 96 AF D9 07 17 6B 43 53 D1 8A 9C ED F7 FB F3 7F 5C 30 42 A5 EB 94 A5 EC 52 7A 40 BC 9D 44 98 DF 7D 33 ED 7F 55 8D DC 6A 20 8A 24 5A 9E 97 5E 62 05 30 0A 06 08 2A 86 48 CE 3D 04 03 02 03 47 00 30 44 02 20 12 48 EF D8 46 88 1F F3 A7 AA F6 FF 87 7F 80 5B 79 B8 09 9D AD CD BB AD 68 48 AA 8E 12 8A E3 D9 02 F9 
00000141 [1946149872] openct/proto-t1.c:356:t1_transceive() 
00000027 [1946149872] sending: 00 80 00 80 
00000042 [1946149872] -> 000000 6F 04 00 00 00 00 14 00 00 00 00 80 00 80 
00005726 [1946149872] <- 000000 80 27 00 00 00 00 14 00 00 00 00 00 23 20 0A A4 D5 FD F9 6B 2F 43 D6 2C 16 01 4B 95 80 AF 60 14 8E 6A 45 7F F9 D1 A8 D3 C4 D5 13 15 53 CD 90 00 87 
00000078 [1946149872] received: 00 00 23 20 0A A4 D5 FD F9 6B 2F 43 D6 2C 16 01 4B 95 80 AF 60 14 8E 6A 45 7F F9 D1 A8 D3 C4 D5 13 15 53 CD 90 00 87 
00000326 [1946149872] SW: 01 1D 30 82 01 19 30 81 C1 A0 03 02 01 02 02 09 00 A7 9C 07 DC 13 D4 F4 16 30 0A 06 08 2A 86 48 CE 3D 04 03 02 30 13 31 11 30 0F 06 03 55 04 03 13 08 43 72 79 70 74 6E 6F 78 30 1E 17 0D 31 38 31 32 30 39 30 37 30 34 35 38 5A 17 0D 32 32 31 32 30 38 30 37 30 34 35 38 5A 30 13 31 11 30 0F 06 03 55 04 03 13 08 43 72 79 70 74 6E 6F 78 30 59 30 13 06 07 2A 86 48 CE 3D 02 01 06 08 2A 86 48 CE 3D 03 01 07 03 42 00 04 83 12 E1 14 1B 91 55 B7 6A EC 56 28 0E 2C 46 96 AF D9 07 17 6B 43 53 D1 8A 9C ED F7 FB F3 7F 5C 30 42 A5 EB 94 A5 EC 52 7A 40 BC 9D 44 98 DF 7D 33 ED 7F 55 8D DC 6A 20 8A 24 5A 9E 97 5E 62 05 30 0A 06 08 2A 86 48 CE 3D 04 03 02 03 47 00 30 44 02 20 12 48 EF D8 46 88 1F F3 A7 AA F6 FF 87 7F 80 5B 79 B8 09 9D AD CD BB AD 68 48 AA 8E 12 8A E3 D9 02 20 0A A4 D5 FD F9 6B 2F 43 D6 2C 16 01 4B 95 80 AF 60 14 8E 6A 45 7F F9 D1 A8 D3 C4 D5 13 15 53 CD 90 00 
00000021 [1946149872] winscard.c:1646:SCardTransmit() UnrefReader() count was: 2
00000019 [1946149872] winscard_svc.c:683:ContextThread() TRANSMIT rv=0x0 for client 15
00046994 [1946149872] winscard_svc.c:362:ContextThread() Received command: TRANSMIT from client 15
00000193 [1946149872] readerfactory.c:848:RFReaderInfoById() RefReader() count was: 1
00000027 [1946149872] winscard.c:1601:SCardTransmit() Send Protocol: T=1
00000038 [1946149872] APDU: 80 F8 00 00 08 FB 9B CC 52 35 9F 4C BD 
00000021 [1946149872] ifdhandler.c:1303:IFDHTransmitToICC() usb:08e6/3437:libudev:0:/dev/bus/usb/001/026 (lun: 0)
00000019 [1946149872] commands.c:2228:CmdXfrBlockTPDU_T1() T=1: 13 and 65548 bytes
00000019 [1946149872] openct/proto-t1.c:580:t1_build() more bit: 0
00000035 [1946149872] sending: 00 00 0D 80 F8 00 00 08 FB 9B CC 52 35 9F 4C BD D8 
00000047 [1946149872] -> 000000 6F 11 00 00 00 00 15 00 00 00 00 00 0D 80 F8 00 00 08 FB 9B CC 52 35 9F 4C BD D8 
00058812 [1946149872] <- 000000 80 97 00 00 00 00 15 00 00 00 00 40 93 43 FB 9B CC 52 35 9F 4C BD 04 79 11 C2 CD B2 11 68 53 16 8E 32 22 6A FF 03 B1 B1 67 9E 73 70 67 23 73 3F DA AB C6 1A 03 F1 1C 93 C6 82 3F 77 DD B1 4B A7 0B 8B 3D A5 92 19 2F 14 2A 80 9E 4A 96 68 11 47 A0 BA 1E 8E C9 D7 A1 30 45 02 21 00 B8 12 49 F6 48 E0 FF C3 EB C8 FE 33 E9 DB 45 0F EA BD 27 BD 55 A9 E9 0A DE 79 19 E7 BB 64 C7 3A 02 20 47 7F FE 15 FF 28 43 BB 9E 37 53 B5 75 A7 5E ED F9 40 BD F0 1E 66 4E 9A 70 9F 50 C8 5C F6 67 07 90 00 58 
00000205 [1946149872] received: 00 40 93 43 FB 9B CC 52 35 9F 4C BD 04 79 11 C2 CD B2 11 68 53 16 8E 32 22 6A FF 03 B1 B1 67 9E 73 70 67 23 73 3F DA AB C6 1A 03 F1 1C 93 C6 82 3F 77 DD B1 4B A7 0B 8B 3D A5 92 19 2F 14 2A 80 9E 4A 96 68 11 47 A0 BA 1E 8E C9 D7 A1 30 45 02 21 00 B8 12 49 F6 48 E0 FF C3 EB C8 FE 33 E9 DB 45 0F EA BD 27 BD 55 A9 E9 0A DE 79 19 E7 BB 64 C7 3A 02 20 47 7F FE 15 FF 28 43 BB 9E 37 53 B5 75 A7 5E ED F9 40 BD F0 1E 66 4E 9A 70 9F 50 C8 5C F6 67 07 90 00 58 
00000027 [1946149872] openct/proto-t1.c:356:t1_transceive() 
00000173 [1946149872] SW: 43 FB 9B CC 52 35 9F 4C BD 04 79 11 C2 CD B2 11 68 53 16 8E 32 22 6A FF 03 B1 B1 67 9E 73 70 67 23 73 3F DA AB C6 1A 03 F1 1C 93 C6 82 3F 77 DD B1 4B A7 0B 8B 3D A5 92 19 2F 14 2A 80 9E 4A 96 68 11 47 A0 BA 1E 8E C9 D7 A1 30 45 02 21 00 B8 12 49 F6 48 E0 FF C3 EB C8 FE 33 E9 DB 45 0F EA BD 27 BD 55 A9 E9 0A DE 79 19 E7 BB 64 C7 3A 02 20 47 7F FE 15 FF 28 43 BB 9E 37 53 B5 75 A7 5E ED F9 40 BD F0 1E 66 4E 9A 70 9F 50 C8 5C F6 67 07 90 00 
00000149 [1946149872] winscard.c:1646:SCardTransmit() UnrefReader() count was: 2
00000028 [1946149872] winscard_svc.c:683:ContextThread() TRANSMIT rv=0x0 for client 15
00173334 [1946149872] winscard_svc.c:362:ContextThread() Received command: TRANSMIT from client 15
00000194 [1946149872] readerfactory.c:848:RFReaderInfoById() RefReader() count was: 1
00000027 [1946149872] winscard.c:1601:SCardTransmit() Send Protocol: T=1
00000215 [1946149872] APDU: 80 FE 00 00 B2 41 04 37 01 02 36 3C 5C E1 53 87 88 30 FF 8B CB 8C 4F FB 4A A6 04 56 84 42 47 02 5F D2 13 48 F0 61 5C E7 7C 10 4F B0 74 4F B8 B4 CB 2A 06 98 11 13 5F FC EB B3 FC 48 0E 8E 25 F0 CA 35 C2 1E 13 EC 1F 5A BA E0 4D 6A 96 DE 3C D1 E7 3B D6 99 E8 8A 19 89 81 FC BA 16 97 33 CF C7 C4 B6 B3 14 77 25 A5 81 01 C0 EA A7 D1 11 D8 81 0C 35 31 76 AD 3D 62 75 A1 C0 A0 C8 15 47 2B 45 FB 5B 3B F7 5C 56 48 D7 54 C1 3E 68 E9 58 95 A2 84 42 B3 7D 6E 58 D2 E0 E2 E0 0A 2B 19 B5 3F C0 9F 71 18 F2 B5 77 7C B7 41 4C 82 C6 5B 71 CE 51 4D A2 0B 3F 6E 58 0E 
00000032 [1946149872] ifdhandler.c:1303:IFDHTransmitToICC() usb:08e6/3437:libudev:0:/dev/bus/usb/001/026 (lun: 0)
00000020 [1946149872] commands.c:2228:CmdXfrBlockTPDU_T1() T=1: 183 and 65548 bytes
00000018 [1946149872] openct/proto-t1.c:580:t1_build() more bit: 0
00000211 [1946149872] sending: 00 40 B7 80 FE 00 00 B2 41 04 37 01 02 36 3C 5C E1 53 87 88 30 FF 8B CB 8C 4F FB 4A A6 04 56 84 42 47 02 5F D2 13 48 F0 61 5C E7 7C 10 4F B0 74 4F B8 B4 CB 2A 06 98 11 13 5F FC EB B3 FC 48 0E 8E 25 F0 CA 35 C2 1E 13 EC 1F 5A BA E0 4D 6A 96 DE 3C D1 E7 3B D6 99 E8 8A 19 89 81 FC BA 16 97 33 CF C7 C4 B6 B3 14 77 25 A5 81 01 C0 EA A7 D1 11 D8 81 0C 35 31 76 AD 3D 62 75 A1 C0 A0 C8 15 47 2B 45 FB 5B 3B F7 5C 56 48 D7 54 C1 3E 68 E9 58 95 A2 84 42 B3 7D 6E 58 D2 E0 E2 E0 0A 2B 19 B5 3F C0 9F 71 18 F2 B5 77 7C B7 41 4C 82 C6 5B 71 CE 51 4D A2 0B 3F 6E 58 0E E1 
00000237 [1946149872] -> 000000 6F BB 00 00 00 00 16 00 00 00 00 40 B7 80 FE 00 00 B2 41 04 37 01 02 36 3C 5C E1 53 87 88 30 FF 8B CB 8C 4F FB 4A A6 04 56 84 42 47 02 5F D2 13 48 F0 61 5C E7 7C 10 4F B0 74 4F B8 B4 CB 2A 06 98 11 13 5F FC EB B3 FC 48 0E 8E 25 F0 CA 35 C2 1E 13 EC 1F 5A BA E0 4D 6A 96 DE 3C D1 E7 3B D6 99 E8 8A 19 89 81 FC BA 16 97 33 CF C7 C4 B6 B3 14 77 25 A5 81 01 C0 EA A7 D1 11 D8 81 0C 35 31 76 AD 3D 62 75 A1 C0 A0 C8 15 47 2B 45 FB 5B 3B F7 5C 56 48 D7 54 C1 3E 68 E9 58 95 A2 84 42 B3 7D 6E 58 D2 E0 E2 E0 0A 2B 19 B5 3F C0 9F 71 18 F2 B5 77 7C B7 41 4C 82 C6 5B 71 CE 51 4D A2 0B 3F 6E 58 0E E1 
01053844 [1946149872] <- 000000 80 06 00 00 00 00 16 00 00 00 00 00 02 90 00 92 
00000079 [1946149872] received: 00 00 02 90 00 92 
00000029 [1946149872] openct/proto-t1.c:356:t1_transceive() 
00000032 [1946149872] SW: 90 00 
00000024 [1946149872] winscard.c:1646:SCardTransmit() UnrefReader() count was: 2
00000026 [1946149872] winscard_svc.c:683:ContextThread() TRANSMIT rv=0x0 for client 15
00001144 [1946149872] winscard_svc.c:362:ContextThread() Received command: DISCONNECT from client 15
00000076 [1946149872] readerfactory.c:848:RFReaderInfoById() RefReader() count was: 1
00000028 [1946149872] winscard.c:884:SCardDisconnect() Active Contexts: 1
00000022 [1946149872] winscard.c:885:SCardDisconnect() dwDisposition: 2
00000032 [1946149872] ifdhandler.c:1821:IFDHICCPresence() usb:08e6/3437:libudev:0:/dev/bus/usb/001/026 (lun: 0)
00000046 [1946149872] -> 000000 65 00 00 00 00 00 17 00 00 00 
00000941 [1946149872] <- 000000 81 00 00 00 00 00 17 00 00 00 
00000058 [1946149872] ifdhandler.c:1942:IFDHICCPresence() Card present
00000030 [1946149872] ifdhandler.c:1154:IFDHPowerICC() action: PowerDown, usb:08e6/3437:libudev:0:/dev/bus/usb/001/026 (lun: 0)
00000046 [1946149872] -> 000000 63 00 00 00 00 00 18 00 00 00 
00009474 [1946149872] <- 000000 81 00 00 00 00 00 18 01 00 00 
00000049 [1946149872] winscard.c:907:SCardDisconnect() powerState: POWER_STATE_UNPOWERED
00000038 [1946149872] ifdhandler.c:381:IFDHGetCapabilities() tag: 0xFB2, usb:08e6/3437:libudev:0:/dev/bus/usb/001/026 (lun: 0)
00000038 [1946149872] winscard.c:1033:SCardDisconnect() Stopping polling thread
00000027 [1946149872] ifdhandler.c:346:IFDHStopPolling() usb:08e6/3437:libudev:0:/dev/bus/usb/001/026 (lun: 0)
00000059 [1946149872] winscard.c:1046:SCardDisconnect() UnrefReader() count was: 2
00000033 [1946149872] winscard_svc.c:548:ContextThread() DISCONNECT rv=0x0 for client 15
00000036 [1974522864] ccid_usb.c:1352:InterruptRead() after (0) (3)
00000034 [1974522864] ccid_usb.c:1367:InterruptRead() InterruptRead (1/26): 3
00000697 [1946149872] winscard_svc.c:362:ContextThread() Received command: RELEASE_CONTEXT from client 15
00000071 [1946149872] winscard.c:229:SCardReleaseContext() Releasing Context: 0x41BFA0B9
00000030 [1946149872] winscard_svc.c:474:ContextThread() RELEASE_CONTEXT rv=0x0 for client 15
00000196 [1946149872] winscard_svc.c:354:ContextThread() Client die: 15
00000129 [1946149872] winscard_svc.c:1057:MSGCleanupClient() Thread is stopping: dwClientID=15, threadContext @0x5a6bc8
00000030 [1946149872] winscard_svc.c:1063:MSGCleanupClient() Freeing SCONTEXT @0x5a6bc8
00002125 [1954542576] winscard_svc.c:362:ContextThread() Received command: CMD_GET_READERS_STATE from client 14
00000782 [1954542576] winscard_svc.c:362:ContextThread() Received command: CMD_GET_READERS_STATE from client 14
00001179 [1995993136] winscard_msg_srv.c:255:ProcessEventsServer() Common channel packet arrival
00000103 [1995993136] winscard_msg_srv.c:267:ProcessEventsServer() ProcessCommonChannelRequest detects: 15
00000034 [1995993136] pcscdaemon.c:133:SVCServiceRunLoop() A new context thread creation is requested: 15
00000394 [1946149872] winscard_svc.c:340:ContextThread() Authorized PC/SC client
00000046 [1946149872] winscard_svc.c:344:ContextThread() Thread is started: dwClientID=15, threadContext @0x5a6bc8
00000215 [1946149872] winscard_svc.c:362:ContextThread() Received command: CMD_VERSION from client 15
00000070 [1946149872] winscard_svc.c:374:ContextThread() Client is protocol version 4:4
00000033 [1946149872] winscard_svc.c:394:ContextThread() CMD_VERSION rv=0x0 for client 15
00000425 [1946149872] winscard_svc.c:362:ContextThread() Received command: ESTABLISH_CONTEXT from client 15
00000352 [1946149872] winscard.c:215:SCardEstablishContext() Establishing Context: 0x3DCDCC35
00000042 [1946149872] winscard_svc.c:459:ContextThread() ESTABLISH_CONTEXT rv=0x0 for client 15
00001093 [1946149872] winscard_svc.c:362:ContextThread() Received command: CONNECT from client 15
00000162 [1946149872] winscard_svc.c:497:ContextThread() Authorized client for 'Gemalto PC Twin Reader (77803048) 00 00'
00000038 [1946149872] winscard.c:259:SCardConnect() Attempting Connect to Gemalto PC Twin Reader (77803048) 00 00 using protocol: 2
00000026 [1946149872] readerfactory.c:821:RFReaderInfo() RefReader() count was: 1
00000032 [1946149872] ifdhandler.c:1821:IFDHICCPresence() usb:08e6/3437:libudev:0:/dev/bus/usb/001/026 (lun: 0)
00000048 [1946149872] -> 000000 65 00 00 00 00 00 19 00 00 00 
00001281 [1946149872] <- 000000 81 00 00 00 00 00 19 01 00 00 
00000057 [1946149872] ifdhandler.c:1942:IFDHICCPresence() Card present
00000035 [1946149872] ifdhandler.c:1154:IFDHPowerICC() action: PowerUp, usb:08e6/3437:libudev:0:/dev/bus/usb/001/026 (lun: 0)
00000048 [1946149872] -> 000000 62 00 00 00 00 00 1A 01 00 00 
00063285 [1946149872] <- 000000 80 14 00 00 00 00 1A 00 00 00 3B FA 18 00 00 81 31 FE 45 4A 54 61 78 43 6F 72 65 56 31 B2 
00000063 [1946149872] winscard.c:332:SCardConnect() power up complete.
00000053 [1946149872] Card ATR: 3B FA 18 00 00 81 31 FE 45 4A 54 61 78 43 6F 72 65 56 31 B2 
00000023 [1946149872] winscard.c:352:SCardConnect() powerState: POWER_STATE_IN_USE
00000027 [1946149872] prothandler.c:108:PHSetProtocol() Attempting PTS to T=1
00000031 [1946149872] ifdhandler.c:695:IFDHSetProtocolParameters() protocol T=1, usb:08e6/3437:libudev:0:/dev/bus/usb/001/026 (lun: 0)
00000034 [1946149872] ifdhandler.c:2036:find_baud_rate() Card baud rate: 154838
00000023 [1946149872] ifdhandler.c:2045:find_baud_rate() Reader can do: 12903
00000021 [1946149872] ifdhandler.c:2045:find_baud_rate() Reader can do: 25806
00000020 [1946149872] ifdhandler.c:2045:find_baud_rate() Reader can do: 51613
00000025 [1946149872] ifdhandler.c:2045:find_baud_rate() Reader can do: 103226
00000021 [1946149872] ifdhandler.c:2045:find_baud_rate() Reader can do: 206452
00000020 [1946149872] ifdhandler.c:2045:find_baud_rate() Reader can do: 412903
00000020 [1946149872] ifdhandler.c:2045:find_baud_rate() Reader can do: 825806
00000020 [1946149872] ifdhandler.c:2045:find_baud_rate() Reader can do: 154839
00000024 [1946149872] ifdhandler.c:818:IFDHSetProtocolParameters() Set speed to 154838 bauds
00000024 [1946149872] towitoko/atr.c:334:ATR_GetDefaultProtocol() T=1 Protocol Found
00000020 [1946149872] towitoko/atr.c:342:ATR_GetDefaultProtocol() default protocol: T=1
00000021 [1946149872] towitoko/atr.c:334:ATR_GetDefaultProtocol() T=1 Protocol Found
00000027 [1946149872] PPS: Sending request: FF 11 18 F6 
00000051 [1946149872] -> 000000 6F 04 00 00 00 00 1B 00 00 00 FF 11 18 F6 
00019708 [1946149872] <- 000000 80 04 00 00 00 00 1B 00 00 00 FF 11 18 F6 
00000055 [1946149872] PPS: Receiving confirm: FF 11 18 F6 
00000032 [1946149872] ifdhandler.c:979:IFDHSetProtocolParameters() BWI/CWI (TB3) present: 0x45
00000029 [1946149872] ifdhandler.c:1013:IFDHSetProtocolParameters() IFSC (TA3) present: 254
00000023 [1946149872] ifdhandler.c:1017:IFDHSetProtocolParameters() Timeout: 2282 ms
00000029 [1946149872] commands.c:2254:SetParameters() length: 7 bytes
00000051 [1946149872] -> 000000 61 07 00 00 00 00 1C 01 00 00 18 10 00 45 00 FE 00 
00001978 [1946149872] <- 000000 82 07 00 00 00 00 1C 00 00 01 18 10 00 45 00 FE 00 
00000045 [1946149872] ifdhandler.c:1074:IFDHSetProtocolParameters() IFSC (TA3) present: 254
00000025 [1946149872] ifdhandler.c:1081:IFDHSetProtocolParameters() Negotiate IFSD at 254
00000036 [1946149872] sending: 00 C1 01 FE 3E 
00000050 [1946149872] -> 000000 6F 05 00 00 00 00 1D 00 00 00 00 C1 01 FE 3E 
00003311 [1946149872] <- 000000 80 05 00 00 00 00 1D 00 00 00 00 E1 01 FE 1E 
00000045 [1946149872] received: 00 E1 01 FE 1E 
00000034 [1946149872] ifdhandler.c:1087:IFDHSetProtocolParameters() T=1: IFSC=254, IFSD=254
00000025 [1946149872] winscard.c:431:SCardConnect() Active Protocol: T=1
00000036 [1946149872] winscard.c:456:SCardConnect() hCard Identity: 59ff3498
00000030 [1946149872] winscard.c:518:SCardConnect() UnrefReader() count was: 2
00000033 [1946149872] winscard_svc.c:511:ContextThread() CONNECT rv=0x0 for client 15
00002420 [1946149872] winscard_svc.c:362:ContextThread() Received command: TRANSMIT from client 15
00000293 [1946149872] readerfactory.c:848:RFReaderInfoById() RefReader() count was: 1
00000044 [1946149872] winscard.c:1601:SCardTransmit() Send Protocol: T=1
00000081 [1946149872] APDU: 00 A4 04 00 07 A0 00 00 10 00 01 01 
00000036 [1946149872] ifdhandler.c:1303:IFDHTransmitToICC() usb:08e6/3437:libudev:0:/dev/bus/usb/001/026 (lun: 0)
00000240 [1946149872] commands.c:2228:CmdXfrBlockTPDU_T1() T=1: 12 and 65548 bytes
00000053 [1946149872] openct/proto-t1.c:580:t1_build() more bit: 0
00000058 [1946149872] sending: 00 00 0C 00 A4 04 00 07 A0 00 00 10 00 01 01 1B 
00000573 [1946149872] -> 000000 6F 10 00 00 00 00 1E 00 00 00 00 00 0C 00 A4 04 00 07 A0 00 00 10 00 01 01 1B 
00076079 [1946149872] <- 000000 80 2A 00 00 00 00 1E 00 00 00 00 00 26 50 00 08 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 90 00 EE 
00000123 [1946149872] received: 00 00 26 50 00 08 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 90 00 EE 
00000034 [1946149872] openct/proto-t1.c:356:t1_transceive() 
00000267 [1946149872] SW: 50 00 08 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 90 00 
00000041 [1946149872] winscard.c:1646:SCardTransmit() UnrefReader() count was: 2
00000029 [1946149872] winscard_svc.c:683:ContextThread() TRANSMIT rv=0x0 for client 15
00001866 [1946149872] winscard_svc.c:362:ContextThread() Received command: TRANSMIT from client 15
00000161 [1946149872] readerfactory.c:848:RFReaderInfoById() RefReader() count was: 1
00000035 [1946149872] winscard.c:1601:SCardTransmit() Send Protocol: T=1
00000042 [1946149872] APDU: 80 FE 00 00 01 01 
00000031 [1946149872] ifdhandler.c:1303:IFDHTransmitToICC() usb:08e6/3437:libudev:0:/dev/bus/usb/001/026 (lun: 0)
00000029 [1946149872] commands.c:2228:CmdXfrBlockTPDU_T1() T=1: 6 and 65548 bytes
00000026 [1946149872] openct/proto-t1.c:580:t1_build() more bit: 0
00000039 [1946149872] sending: 00 40 06 80 FE 00 00 01 01 38 
00000089 [1946149872] -> 000000 6F 0A 00 00 00 00 1F 00 00 00 00 40 06 80 FE 00 00 01 01 38 
00006126 [1946149872] <- 000000 80 06 00 00 00 00 1F 00 00 00 00 40 02 6D 00 2F 
00000055 [1946149872] received: 00 40 02 6D 00 2F 
00000031 [1946149872] openct/proto-t1.c:356:t1_transceive() 
00000031 [1946149872] SW: 6D 00 
00000023 [1946149872] winscard.c:1646:SCardTransmit() UnrefReader() count was: 2
00000026 [1946149872] winscard_svc.c:683:ContextThread() TRANSMIT rv=0x0 for client 15
00004186 [1946149872] winscard_svc.c:362:ContextThread() Received command: TRANSMIT from client 15
00000254 [1946149872] readerfactory.c:848:RFReaderInfoById() RefReader() count was: 1
00000100 [1946149872] winscard.c:1601:SCardTransmit() Send Protocol: T=1
00000317 [1946149872] APDU: 80 F8 00 00 08 29 F6 37 64 EC 6F FA 83 
00000048 [1946149872] ifdhandler.c:1303:IFDHTransmitToICC() usb:08e6/3437:libudev:0:/dev/bus/usb/001/026 (lun: 0)
00000031 [1946149872] commands.c:2228:CmdXfrBlockTPDU_T1() T=1: 13 and 65548 bytes
00000028 [1946149872] openct/proto-t1.c:580:t1_build() more bit: 0
00000118 [1946149872] sending: 00 00 0D 80 F8 00 00 08 29 F6 37 64 EC 6F FA 83 0B 
00000077 [1946149872] -> 000000 6F 11 00 00 00 00 20 00 00 00 00 00 0D 80 F8 00 00 08 29 F6 37 64 EC 6F FA 83 0B 
00059211 [1946149872] <- 000000 80 96 00 00 00 00 20 00 00 00 00 00 92 43 29 F6 37 64 EC 6F FA 83 04 8D 75 9B 0A 5A 81 85 C7 16 3B 25 1D 7B 73 E1 64 77 CB DF 1C 41 17 85 6A 73 49 37 DB DA F7 E2 2A ED 36 FF 40 16 6C 0A DB 73 3B 49 26 6C 53 EC EC 4F 4F 84 C7 B8 75 B5 3A E8 61 FC 87 B7 DB B3 0C 30 44 02 20 44 83 BA C3 7A F8 8D C0 0E 22 E8 9C 5B 51 B2 5B 3B D7 A9 C9 03 C0 E4 A8 C3 F3 8F 05 5F FE 96 E1 02 20 6C 13 69 D9 23 D8 AA B7 37 73 EC 4B BD 11 57 95 8D 01 83 D2 B1 20 54 5F 21 59 31 F5 46 A6 3A 0C 90 00 01 
00000297 [1946149872] received: 00 00 92 43 29 F6 37 64 EC 6F FA 83 04 8D 75 9B 0A 5A 81 85 C7 16 3B 25 1D 7B 73 E1 64 77 CB DF 1C 41 17 85 6A 73 49 37 DB DA F7 E2 2A ED 36 FF 40 16 6C 0A DB 73 3B 49 26 6C 53 EC EC 4F 4F 84 C7 B8 75 B5 3A E8 61 FC 87 B7 DB B3 0C 30 44 02 20 44 83 BA C3 7A F8 8D C0 0E 22 E8 9C 5B 51 B2 5B 3B D7 A9 C9 03 C0 E4 A8 C3 F3 8F 05 5F FE 96 E1 02 20 6C 13 69 D9 23 D8 AA B7 37 73 EC 4B BD 11 57 95 8D 01 83 D2 B1 20 54 5F 21 59 31 F5 46 A6 3A 0C 90 00 01 
00000042 [1946149872] openct/proto-t1.c:356:t1_transceive() 
00000262 [1946149872] SW: 43 29 F6 37 64 EC 6F FA 83 04 8D 75 9B 0A 5A 81 85 C7 16 3B 25 1D 7B 73 E1 64 77 CB DF 1C 41 17 85 6A 73 49 37 DB DA F7 E2 2A ED 36 FF 40 16 6C 0A DB 73 3B 49 26 6C 53 EC EC 4F 4F 84 C7 B8 75 B5 3A E8 61 FC 87 B7 DB B3 0C 30 44 02 20 44 83 BA C3 7A F8 8D C0 0E 22 E8 9C 5B 51 B2 5B 3B D7 A9 C9 03 C0 E4 A8 C3 F3 8F 05 5F FE 96 E1 02 20 6C 13 69 D9 23 D8 AA B7 37 73 EC 4B BD 11 57 95 8D 01 83 D2 B1 20 54 5F 21 59 31 F5 46 A6 3A 0C 90 00 
00000032 [1946149872] winscard.c:1646:SCardTransmit() UnrefReader() count was: 2
00000099 [1946149872] winscard_svc.c:683:ContextThread() TRANSMIT rv=0x0 for client 15
00005414 [1946149872] winscard_svc.c:362:ContextThread() Received command: TRANSMIT from client 15
00000108 [1946149872] readerfactory.c:848:RFReaderInfoById() RefReader() count was: 1
00000031 [1946149872] winscard.c:1601:SCardTransmit() Send Protocol: T=1
00000047 [1946149872] APDU: 80 F7 00 00 00 00 00 
00000030 [1946149872] ifdhandler.c:1303:IFDHTransmitToICC() usb:08e6/3437:libudev:0:/dev/bus/usb/001/026 (lun: 0)
00000026 [1946149872] commands.c:2228:CmdXfrBlockTPDU_T1() T=1: 7 and 65548 bytes
00000025 [1946149872] openct/proto-t1.c:580:t1_build() more bit: 0
00000045 [1946149872] sending: 00 40 07 80 F7 00 00 00 00 00 30 
00000061 [1946149872] -> 000000 6F 0B 00 00 00 00 21 00 00 00 00 40 07 80 F7 00 00 00 00 00 30 
00030723 [1946149872] <- 000000 80 02 01 00 00 00 21 00 00 00 00 60 FE 01 1D 30 82 01 19 30 81 C1 A0 03 02 01 02 02 09 00 A7 9C 07 DC 13 D4 F4 16 30 0A 06 08 2A 86 48 CE 3D 04 03 02 30 13 31 11 30 0F 06 03 55 04 03 13 08 43 72 79 70 74 6E 6F 78 30 1E 17 0D 31 38 31 32 30 39 30 37 30 34 35 38 5A 17 0D 32 32 31 32 30 38 30 37 30 34 35 38 5A 30 13 31 11 30 0F 06 03 55 04 03 13 08 43 72 79 70 74 6E 6F 78 30 59 30 13 06 07 2A 86 48 CE 3D 02 01 06 08 2A 86 48 CE 3D 03 01 07 03 42 00 04 83 12 E1 14 1B 91 55 B7 6A EC 56 28 0E 2C 46 96 AF D9 07 17 6B 43 53 D1 8A 9C ED F7 FB F3 7F 5C 30 42 A5 EB 94 A5 EC 52 7A 40 BC 9D 44 98 DF 7D 33 ED 7F 55 8D DC 6A 20 8A 24 5A 9E 97 5E 62 05 30 0A 06 08 2A 86 48 CE 3D 04 03 02 03 47 00 30 44 02 20 12 48 EF D8 46 88 1F F3 A7 AA F6 FF 87 7F 80 5B 79 B8 09 9D AD CD BB AD 68 48 AA 8E 12 8A E3 D9 02 F9 
00000482 [1946149872] received: 00 60 FE 01 1D 30 82 01 19 30 81 C1 A0 03 02 01 02 02 09 00 A7 9C 07 DC 13 D4 F4 16 30 0A 06 08 2A 86 48 CE 3D 04 03 02 30 13 31 11 30 0F 06 03 55 04 03 13 08 43 72 79 70 74 6E 6F 78 30 1E 17 0D 31 38 31 32 30 39 30 37 30 34 35 38 5A 17 0D 32 32 31 32 30 38 30 37 30 34 35 38 5A 30 13 31 11 30 0F 06 03 55 04 03 13 08 43 72 79 70 74 6E 6F 78 30 59 30 13 06 07 2A 86 48 CE 3D 02 01 06 08 2A 86 48 CE 3D 03 01 07 03 42 00 04 83 12 E1 14 1B 91 55 B7 6A EC 56 28 0E 2C 46 96 AF D9 07 17 6B 43 53 D1 8A 9C ED F7 FB F3 7F 5C 30 42 A5 EB 94 A5 EC 52 7A 40 BC 9D 44 98 DF 7D 33 ED 7F 55 8D DC 6A 20 8A 24 5A 9E 97 5E 62 05 30 0A 06 08 2A 86 48 CE 3D 04 03 02 03 47 00 30 44 02 20 12 48 EF D8 46 88 1F F3 A7 AA F6 FF 87 7F 80 5B 79 B8 09 9D AD CD BB AD 68 48 AA 8E 12 8A E3 D9 02 F9 
00000043 [1946149872] openct/proto-t1.c:356:t1_transceive() 
00000038 [1946149872] sending: 00 80 00 80 
00000049 [1946149872] -> 000000 6F 04 00 00 00 00 22 00 00 00 00 80 00 80 
00007089 [1946149872] <- 000000 80 27 00 00 00 00 22 00 00 00 00 00 23 20 0A A4 D5 FD F9 6B 2F 43 D6 2C 16 01 4B 95 80 AF 60 14 8E 6A 45 7F F9 D1 A8 D3 C4 D5 13 15 53 CD 90 00 87 
00000102 [1946149872] received: 00 00 23 20 0A A4 D5 FD F9 6B 2F 43 D6 2C 16 01 4B 95 80 AF 60 14 8E 6A 45 7F F9 D1 A8 D3 C4 D5 13 15 53 CD 90 00 87 
00000566 [1946149872] SW: 01 1D 30 82 01 19 30 81 C1 A0 03 02 01 02 02 09 00 A7 9C 07 DC 13 D4 F4 16 30 0A 06 08 2A 86 48 CE 3D 04 03 02 30 13 31 11 30 0F 06 03 55 04 03 13 08 43 72 79 70 74 6E 6F 78 30 1E 17 0D 31 38 31 32 30 39 30 37 30 34 35 38 5A 17 0D 32 32 31 32 30 38 30 37 30 34 35 38 5A 30 13 31 11 30 0F 06 03 55 04 03 13 08 43 72 79 70 74 6E 6F 78 30 59 30 13 06 07 2A 86 48 CE 3D 02 01 06 08 2A 86 48 CE 3D 03 01 07 03 42 00 04 83 12 E1 14 1B 91 55 B7 6A EC 56 28 0E 2C 46 96 AF D9 07 17 6B 43 53 D1 8A 9C ED F7 FB F3 7F 5C 30 42 A5 EB 94 A5 EC 52 7A 40 BC 9D 44 98 DF 7D 33 ED 7F 55 8D DC 6A 20 8A 24 5A 9E 97 5E 62 05 30 0A 06 08 2A 86 48 CE 3D 04 03 02 03 47 00 30 44 02 20 12 48 EF D8 46 88 1F F3 A7 AA F6 FF 87 7F 80 5B 79 B8 09 9D AD CD BB AD 68 48 AA 8E 12 8A E3 D9 02 20 0A A4 D5 FD F9 6B 2F 43 D6 2C 16 01 4B 95 80 AF 60 14 8E 6A 45 7F F9 D1 A8 D3 C4 D5 13 15 53 CD 90 00 
00000043 [1946149872] winscard.c:1646:SCardTransmit() UnrefReader() count was: 2
00000033 [1946149872] winscard_svc.c:683:ContextThread() TRANSMIT rv=0x0 for client 15
00077903 [1946149872] winscard_svc.c:362:ContextThread() Received command: TRANSMIT from client 15
00000129 [1946149872] readerfactory.c:848:RFReaderInfoById() RefReader() count was: 1
00000034 [1946149872] winscard.c:1601:SCardTransmit() Send Protocol: T=1
00000058 [1946149872] APDU: 80 F8 00 00 08 DE 6F C3 6D 7F 19 D8 81 
00000035 [1946149872] ifdhandler.c:1303:IFDHTransmitToICC() usb:08e6/3437:libudev:0:/dev/bus/usb/001/026 (lun: 0)
00000029 [1946149872] commands.c:2228:CmdXfrBlockTPDU_T1() T=1: 13 and 65548 bytes
00000026 [1946149872] openct/proto-t1.c:580:t1_build() more bit: 0
00000056 [1946149872] sending: 00 00 0D 80 F8 00 00 08 DE 6F C3 6D 7F 19 D8 81 5D 
00000073 [1946149872] -> 000000 6F 11 00 00 00 00 23 00 00 00 00 00 0D 80 F8 00 00 08 DE 6F C3 6D 7F 19 D8 81 5D 
00059919 [1946149872] <- 000000 80 98 00 00 00 00 23 00 00 00 00 40 94 43 DE 6F C3 6D 7F 19 D8 81 04 8D 75 9B 0A 5A 81 85 C7 16 3B 25 1D 7B 73 E1 64 77 CB DF 1C 41 17 85 6A 73 49 37 DB DA F7 E2 2A ED 36 FF 40 16 6C 0A DB 73 3B 49 26 6C 53 EC EC 4F 4F 84 C7 B8 75 B5 3A E8 61 FC 87 B7 DB B3 0C 30 46 02 21 00 98 67 1B 49 8A CF 72 24 0D B8 E9 C0 CA E3 F6 60 D7 AE 64 04 FF 4D 76 4E A4 0C 87 6D 92 28 32 6A 02 21 00 E0 5A AE EE 17 67 B3 DD 67 13 30 67 24 99 A1 B5 11 71 B2 65 5B CC C3 82 BF 3F 37 30 D0 ED E6 A3 90 00 61 
00000212 [1946149872] received: 00 40 94 43 DE 6F C3 6D 7F 19 D8 81 04 8D 75 9B 0A 5A 81 85 C7 16 3B 25 1D 7B 73 E1 64 77 CB DF 1C 41 17 85 6A 73 49 37 DB DA F7 E2 2A ED 36 FF 40 16 6C 0A DB 73 3B 49 26 6C 53 EC EC 4F 4F 84 C7 B8 75 B5 3A E8 61 FC 87 B7 DB B3 0C 30 46 02 21 00 98 67 1B 49 8A CF 72 24 0D B8 E9 C0 CA E3 F6 60 D7 AE 64 04 FF 4D 76 4E A4 0C 87 6D 92 28 32 6A 02 21 00 E0 5A AE EE 17 67 B3 DD 67 13 30 67 24 99 A1 B5 11 71 B2 65 5B CC C3 82 BF 3F 37 30 D0 ED E6 A3 90 00 61 
00000032 [1946149872] openct/proto-t1.c:356:t1_transceive() 
00000080 [1974522864] ifdhandler.c:1821:IFDHICCPresence() usb:08e6/3437:libudev:0:/dev/bus/usb/001/026 (lun: 0)
00000051 [1974522864] -> 000000 65 00 00 00 00 00 24 00 00 00 
00000067 [1946149872] SW: 43 DE 6F C3 6D 7F 19 D8 81 04 8D 75 9B 0A 5A 81 85 C7 16 3B 25 1D 7B 73 E1 64 77 CB DF 1C 41 17 85 6A 73 49 37 DB DA F7 E2 2A ED 36 FF 40 16 6C 0A DB 73 3B 49 26 6C 53 EC EC 4F 4F 84 C7 B8 75 B5 3A E8 61 FC 87 B7 DB B3 0C 30 46 02 21 00 98 67 1B 49 8A CF 72 24 0D B8 E9 C0 CA E3 F6 60 D7 AE 64 04 FF 4D 76 4E A4 0C 87 6D 92 28 32 6A 02 21 00 E0 5A AE EE 17 67 B3 DD 67 13 30 67 24 99 A1 B5 11 71 B2 65 5B CC C3 82 BF 3F 37 30 D0 ED E6 A3 90 00 
00000023 [1946149872] winscard.c:1646:SCardTransmit() UnrefReader() count was: 2
00000025 [1946149872] winscard_svc.c:683:ContextThread() TRANSMIT rv=0x0 for client 15
00000622 [1974522864] <- 000000 81 00 00 00 00 00 24 00 00 00 
00000037 [1974522864] ifdhandler.c:1942:IFDHICCPresence() Card present
00000047 [1974522864] ifdhandler.c:310:IFDHPolling() usb:08e6/3437:libudev:0:/dev/bus/usb/001/026 (lun: 0) 600000 ms
00000035 [1974522864] ccid_usb.c:1306:InterruptRead() before (0)
00100104 [1946149872] winscard_svc.c:362:ContextThread() Received command: TRANSMIT from client 15
00000105 [1946149872] readerfactory.c:848:RFReaderInfoById() RefReader() count was: 1
00000022 [1946149872] winscard.c:1601:SCardTransmit() Send Protocol: T=1
00000103 [1946149872] APDU: 80 10 00 00 41 04 A3 8B 5A 67 B9 62 22 54 47 19 CC A6 B9 15 3A 16 85 80 F0 FA 70 2A 34 DF 70 7B E3 FA 42 31 06 F5 1E 91 EA A9 67 3B 3C 89 2B 55 96 A9 30 95 5F C4 DD 52 FD F1 70 F6 8E 08 15 13 0F F6 61 DC 8C E1 
00000024 [1946149872] ifdhandler.c:1303:IFDHTransmitToICC() usb:08e6/3437:libudev:0:/dev/bus/usb/001/026 (lun: 0)
00000023 [1946149872] commands.c:2228:CmdXfrBlockTPDU_T1() T=1: 70 and 65548 bytes
00000023 [1946149872] openct/proto-t1.c:580:t1_build() more bit: 0
00000330 [1946149872] sending: 00 40 46 80 10 00 00 41 04 A3 8B 5A 67 B9 62 22 54 47 19 CC A6 B9 15 3A 16 85 80 F0 FA 70 2A 34 DF 70 7B E3 FA 42 31 06 F5 1E 91 EA A9 67 3B 3C 89 2B 55 96 A9 30 95 5F C4 DD 52 FD F1 70 F6 8E 08 15 13 0F F6 61 DC 8C E1 05 
00000128 [1946149872] -> 000000 6F 4A 00 00 00 00 25 00 00 00 00 40 46 80 10 00 00 41 04 A3 8B 5A 67 B9 62 22 54 47 19 CC A6 B9 15 3A 16 85 80 F0 FA 70 2A 34 DF 70 7B E3 FA 42 31 06 F5 1E 91 EA A9 67 3B 3C 89 2B 55 96 A9 30 95 5F C4 DD 52 FD F1 70 F6 8E 08 15 13 0F F6 61 DC 8C E1 05 
00046170 [1946149872] <- 000000 80 36 00 00 00 00 25 00 00 00 00 00 32 98 9A EC 44 59 D1 11 67 31 2D D0 81 39 F8 8A 71 63 31 53 0A AA FE 60 6E AF A5 53 D2 CC 64 29 29 D1 94 CE DB C8 60 C5 F4 A5 9D 95 1D CA EB A1 63 90 00 69 
00000107 [1946149872] received: 00 00 32 98 9A EC 44 59 D1 11 67 31 2D D0 81 39 F8 8A 71 63 31 53 0A AA FE 60 6E AF A5 53 D2 CC 64 29 29 D1 94 CE DB C8 60 C5 F4 A5 9D 95 1D CA EB A1 63 90 00 69 
00000024 [1946149872] openct/proto-t1.c:356:t1_transceive() 
00000071 [1946149872] SW: 98 9A EC 44 59 D1 11 67 31 2D D0 81 39 F8 8A 71 63 31 53 0A AA FE 60 6E AF A5 53 D2 CC 64 29 29 D1 94 CE DB C8 60 C5 F4 A5 9D 95 1D CA EB A1 63 90 00 
00000019 [1946149872] winscard.c:1646:SCardTransmit() UnrefReader() count was: 2
00000020 [1946149872] winscard_svc.c:683:ContextThread() TRANSMIT rv=0x0 for client 15
00180680 [1946149872] winscard_svc.c:362:ContextThread() Received command: TRANSMIT from client 15
00000101 [1946149872] readerfactory.c:848:RFReaderInfoById() RefReader() count was: 1
00000024 [1946149872] winscard.c:1601:SCardTransmit() Send Protocol: T=1
00000130 [1946149872] APDU: 80 11 00 00 40 D7 AC 4B 2E 5C 23 9D 85 77 BD 97 07 27 72 8A B4 E0 B9 AA 6F 42 E6 10 E4 61 E7 54 C9 99 51 32 03 84 62 1E 6E 3B 24 7D C2 C2 A1 2D 2C 5A D0 F1 4C 7F 91 3F 3E 14 89 A2 57 D3 F5 A2 7C 18 1D 6C A0 
00000028 [1946149872] ifdhandler.c:1303:IFDHTransmitToICC() usb:08e6/3437:libudev:0:/dev/bus/usb/001/026 (lun: 0)
00000046 [1946149872] commands.c:2228:CmdXfrBlockTPDU_T1() T=1: 69 and 65548 bytes
00000022 [1946149872] openct/proto-t1.c:580:t1_build() more bit: 0
00000096 [1946149872] sending: 00 00 45 80 11 00 00 40 D7 AC 4B 2E 5C 23 9D 85 77 BD 97 07 27 72 8A B4 E0 B9 AA 6F 42 E6 10 E4 61 E7 54 C9 99 51 32 03 84 62 1E 6E 3B 24 7D C2 C2 A1 2D 2C 5A D0 F1 4C 7F 91 3F 3E 14 89 A2 57 D3 F5 A2 7C 18 1D 6C A0 27 
00000335 [1946149872] -> 000000 6F 49 00 00 00 00 26 00 00 00 00 00 45 80 11 00 00 40 D7 AC 4B 2E 5C 23 9D 85 77 BD 97 07 27 72 8A B4 E0 B9 AA 6F 42 E6 10 E4 61 E7 54 C9 99 51 32 03 84 62 1E 6E 3B 24 7D C2 C2 A1 2D 2C 5A D0 F1 4C 7F 91 3F 3E 14 89 A2 57 D3 F5 A2 7C 18 1D 6C A0 27 
05000358 [1946149872] ccid_usb.c:859:WriteUSB() write failed (1/26): -7 LIBUSB_ERROR_TIMEOUT
00000103 [1946149872] openct/proto-t1.c:215:t1_transceive() fatal: transmit/receive failed
00000037 [1946149872] SW: 
00000056 [1946149872] ifdwrapper.c:543:IFDTransmit() Card not transacted: 612
00000031 [1946149872] winscard.c:1626:SCardTransmit() Card not transacted: 0x80100016
00000023 [1946149872] winscard.c:1646:SCardTransmit() UnrefReader() count was: 2
00000032 [1946149872] winscard_svc.c:683:ContextThread() TRANSMIT rv=0x80100016 for client 15
00059086 [1946149872] winscard_svc.c:362:ContextThread() Received command: DISCONNECT from client 15
00000131 [1946149872] readerfactory.c:848:RFReaderInfoById() RefReader() count was: 1
00000039 [1946149872] winscard.c:884:SCardDisconnect() Active Contexts: 1
00000025 [1946149872] winscard.c:885:SCardDisconnect() dwDisposition: 2
00000036 [1946149872] ifdhandler.c:1821:IFDHICCPresence() usb:08e6/3437:libudev:0:/dev/bus/usb/001/026 (lun: 0)
00000058 [1946149872] -> 000000 65 00 00 00 00 00 27 00 00 00 
05000316 [1946149872] ccid_usb.c:859:WriteUSB() write failed (1/26): -7 LIBUSB_ERROR_TIMEOUT
00000078 [1946149872] ifdwrapper.c:364:IFDStatusICC() Card not transacted: 612
00000032 [1946149872] winscard.c:907:SCardDisconnect() powerState: POWER_STATE_UNPOWERED
00000028 [1946149872] winscard.c:933:SCardDisconnect() Error powering down card: -2146435050 0x80100016
00000046 [1946149872] ifdhandler.c:381:IFDHGetCapabilities() tag: 0xFB2, usb:08e6/3437:libudev:0:/dev/bus/usb/001/026 (lun: 0)
00000027 [1946149872] winscard.c:1033:SCardDisconnect() Stopping polling thread
00000026 [1946149872] ifdhandler.c:346:IFDHStopPolling() usb:08e6/3437:libudev:0:/dev/bus/usb/001/026 (lun: 0)
00000064 [1946149872] winscard.c:1046:SCardDisconnect() UnrefReader() count was: 2
00000041 [1946149872] winscard_svc.c:548:ContextThread() DISCONNECT rv=0x0 for client 15
00000042 [1974522864] ccid_usb.c:1352:InterruptRead() after (0) (3)
00000056 [1974522864] ccid_usb.c:1367:InterruptRead() InterruptRead (1/26): 3
00000572 [1946149872] winscard_svc.c:362:ContextThread() Received command: RELEASE_CONTEXT from client 15
00000073 [1946149872] winscard.c:229:SCardReleaseContext() Releasing Context: 0x3DCDCC35
00000028 [1946149872] winscard_svc.c:474:ContextThread() RELEASE_CONTEXT rv=0x0 for client 15
00000274 [1946149872] winscard_svc.c:354:ContextThread() Client die: 15
00000226 [1946149872] winscard_svc.c:1057:MSGCleanupClient() Thread is stopping: dwClientID=15, threadContext @0x5a6bc8
00000054 [1946149872] winscard_svc.c:1063:MSGCleanupClient() Freeing SCONTEXT @0x5a6bc8
00043761 [1954542576] winscard_svc.c:354:ContextThread() Client die: 14
00000179 [1954542576] winscard.c:229:SCardReleaseContext() Releasing Context: 0x2414E60F
00000073 [1954542576] winscard_svc.c:1057:MSGCleanupClient() Thread is stopping: dwClientID=14, threadContext @0x5b51c8
00000036 [1954542576] winscard_svc.c:1063:MSGCleanupClient() Freeing SCONTEXT @0x5b51c8
00354925 [1974522864] ifdhandler.c:1821:IFDHICCPresence() usb:08e6/3437:libudev:0:/dev/bus/usb/001/026 (lun: 0)
00000107 [1974522864] -> 000000 65 00 00 00 00 00 28 00 00 00 
05000294 [1974522864] ccid_usb.c:859:WriteUSB() write failed (1/26): -7 LIBUSB_ERROR_TIMEOUT
00000084 [1974522864] ifdwrapper.c:364:IFDStatusICC() Card not transacted: 612
00000028 [1974522864] eventhandler.c:336:EHStatusHandlerThread() Error communicating to: Gemalto PC Twin Reader (77803048) 00 00
00000034 [1974522864] ifdhandler.c:310:IFDHPolling() usb:08e6/3437:libudev:0:/dev/bus/usb/001/026 (lun: 0) 600000 ms
00000024 [1974522864] ccid_usb.c:1306:InterruptRead() before (0)
antonio-fr commented 4 years ago

The former name of this reader is PC USB-SL. I own some P/N HWP108841F.

LudovicRousseau commented 4 years ago
00000130 [1946149872] APDU: 80 11 00 00 40 D7 AC 4B 2E 5C 23 9D 85 77 BD 97 07 27 72 8A B4 E0 B9 AA 6F 42 E6 10 E4 61 E7 54 C9 99 51 32 03 84 62 1E 6E 3B 24 7D C2 C2 A1 2D 2C 5A D0 F1 4C 7F 91 3F 3E 14 89 A2 57 D3 F5 A2 7C 18 1D 6C A0 
00000028 [1946149872] ifdhandler.c:1303:IFDHTransmitToICC() usb:08e6/3437:libudev:0:/dev/bus/usb/001/026 (lun: 0)
00000046 [1946149872] commands.c:2228:CmdXfrBlockTPDU_T1() T=1: 69 and 65548 bytes
00000022 [1946149872] openct/proto-t1.c:580:t1_build() more bit: 0
00000096 [1946149872] sending: 00 00 45 80 11 00 00 40 D7 AC 4B 2E 5C 23 9D 85 77 BD 97 07 27 72 8A B4 E0 B9 AA 6F 42 E6 10 E4 61 E7 54 C9 99 51 32 03 84 62 1E 6E 3B 24 7D C2 C2 A1 2D 2C 5A D0 F1 4C 7F 91 3F 3E 14 89 A2 57 D3 F5 A2 7C 18 1D 6C A0 27 
00000335 [1946149872] -> 000000 6F 49 00 00 00 00 26 00 00 00 00 00 45 80 11 00 00 40 D7 AC 4B 2E 5C 23 9D 85 77 BD 97 07 27 72 8A B4 E0 B9 AA 6F 42 E6 10 E4 61 E7 54 C9 99 51 32 03 84 62 1E 6E 3B 24 7D C2 C2 A1 2D 2C 5A D0 F1 4C 7F 91 3F 3E 14 89 A2 57 D3 F5 A2 7C 18 1D 6C A0 27 
05000358 [1946149872] ccid_usb.c:859:WriteUSB() write failed (1/26): -7 LIBUSB_ERROR_TIMEOUT
00000103 [1946149872] openct/proto-t1.c:215:t1_transceive() fatal: transmit/receive failed

I have no idea why the write command fails. I suspect a reader firmware problem. I am surprised it works fine on Windows.

I suggest to report the problem to the reader manufacturer.

antonio-fr commented 4 years ago

So far, our investigation show that the issue is with frame response from card which are exactly 48 bytes long, whatever the data. When a card response is 48 bytes (50 bytes with trailing 0x9000), the reader gives the response back to USB-CCID and then crashes, requiring a full reset (unplug from USB) of the reader. So, any further communication is not possible after a command with a 48B response, leading to transmit failed of the next command.

Surprisingly, the issue is not present on Windows with the Gemalto driver v4.1.4.0 (automatically installed by Windows).

We're contacting Gemalto.

antonio-fr commented 4 years ago

After investigation on the Gemalto side, they were back with a solution for the RaspberryPi platform. The issue is still present on VMs.

There is a caveat on the Raspberry Pi : the USB support is still somewhat buggy, and need to be configured to make it work more reliably. The RPi is occasionally dropping USB packets for "full-speed" peripherals (such as keyboard, mouse, modems, as well as some audio devices) when working in standard "high-speed" mode. The problem is less acute with the most recent firmware, but it is not completely solved. The only reliable workaround for now is to force all peripherals to run in "full-speed" mode. This has the negative side effect of limiting all peripherals (including the on-board network adapter) to 1.5 MBytes/s (12 Mbps).

To force USB to run in "full-speed" mode on RaspberryPi, one need to add _dwcotg.speed=1 in the /boot/cmdline.txt file :
dwc_otg.lpm_enable=0 console=ttyAMA0,115200 kgdboc=ttyAMA0,115200> dwc_otg.speed=1 console=tty1 root=/dev/mmcblk0p2 rootfstype=ext4> elevator=deadline rootwait

This can be helpful for many CCID readers on the RPi platform, when they're using USB high-spped mode.

LudovicRousseau commented 4 years ago

I also documented the issue on my blog in 2014 https://ludovicrousseau.blogspot.com/2014/04/usb-issues-with-raspberry-pi.html

I missed that you were using a Raspbery Pi in your first message.

antonio-fr commented 4 years ago

By the way, do you have any useful tips for the same issue with virtual machines? We tried many configuration without any success so far.

LudovicRousseau commented 4 years ago

I have no solution for virtual machine. The best is to report the problem to you virtual machine provider and ask for help.