search

LudovicRousseau / CCID

CCID driver
https://ccid.apdu.fr/
GNU Lesser General Public License v2.1
228 stars 79 forks source link

OMNIKEY CardMan 3121 fails with OpenPGP card #79

Closed dangowrt closed 3 years ago

dangowrt commented 3 years ago

When using CardMan 3121 reader with OpenPGP (the only card I got for testing) it fails when using ccid:

pkcs11-tool -I
P:8532; T:0x139856261707584 19:42:20.113 [opensc-pkcs11] pkcs15-din-66291.c:203:sc_pkcs15emu_din_66291_init_ex: called
Cryptoki version 2.20
Manufacturer     OpenSC Project
Library          OpenSC smartcard framework (ver 0.21)
P:8532; T:0x139856261707584 19:42:20.404 [opensc-pkcs11] pkcs15-din-66291.c:203:sc_pkcs15emu_din_66291_init_ex: called
P:8532; T:0x139856261707584 19:42:20.697 [opensc-pkcs11] pkcs15-din-66291.c:203:sc_pkcs15emu_din_66291_init_ex: called
P:8532; T:0x139856261707584 19:42:20.987 [opensc-pkcs11] pkcs15-din-66291.c:203:sc_pkcs15emu_din_66291_init_ex: called
P:8532; T:0x139856261707584 19:42:21.278 [opensc-pkcs11] pkcs15-din-66291.c:203:sc_pkcs15emu_din_66291_init_ex: called
error: PKCS11 function C_GetSlotInfo failed: rv = CKR_FUNCTION_NOT_SUPPORTED (0x54)
Aborting.

Also trying to use GnuPG to sign a message with the key on the card fails, but less verbose:

error: gpg failed to sign the data

When using the proprietary ifdokccid.so driver downloadable from https://www.hidglobal.com/drivers/19364 it all just works fine:

pkcs11-tool -I
Cryptoki version 2.20
Manufacturer     OpenSC Project
Library          OpenSC smartcard framework (ver 0.21)
Using slot 0 with a present token (0x0)

So apparently something is still missing in the free ccid driver and in order to prevent people loosing a similar amount of time I did until I realized that I had to use the proprietary driver instead, it'd be nice to have this at least documented.

LudovicRousseau commented 3 years ago

Please provide a log as described in https://ccid.apdu.fr/#support

dangowrt commented 3 years ago

This is archlinux on x86_64. ccid version 1.4.34

pcsc-lite version 1.9.0.
Copyright (C) 1999-2002 by David Corcoran <corcoran@musclecard.com>.
Copyright (C) 2001-2018 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 x86_64-pc-linux-gnu libsystemd serial usb libudev usbdropdir=/usr/lib/pcsc/drivers ipcdir=/run/pcscd filter configdir=/etc/reader.conf.d

Complete log of failing attempt to gpg --sign

00000000 debuglog.c:299:DebugLogSetLevel() debug level=debug
00000025 debuglog.c:320:DebugLogSetCategory() Debug options: APDU
00000003 [139703017170880] pcscdaemon.c:353:main() Force colored logs
00000133 [139703017170880] configfile.l:293:DBGetReaderListDir() Parsing conf directory: /etc/reader.conf.d
00000035 [139703017170880] configfile.l:329:DBGetReaderListDir() Skipping non regular file: .
00000005 [139703017170880] configfile.l:329:DBGetReaderListDir() Skipping non regular file: ..
00000003 [139703017170880] configfile.l:369:DBGetReaderList() Parsing conf file: /etc/reader.conf.d/libccidtwin
00000058 [139703017170880] pcscdaemon.c:663:main() pcsc-lite 1.9.0 daemon ready.
00005368 [139703017170880] hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/001/001
00000201 [139703017170880] hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/001/001
00000208 [139703017170880] hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x8087, PID: 0x0020, path: /dev/bus/usb/001/002
00000220 [139703017170880] hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x413C, PID: 0x2513, path: /dev/bus/usb/001/003
00000241 [139703017170880] hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x076B, PID: 0x3021, path: /dev/bus/usb/001/009
00000011 [139703017170880] hotplug_libudev.c:440:HPAddDevice() Adding USB device: OMNIKEY AG CardMan 3121
00000056 [139703017170880] readerfactory.c:1074:RFInitializeReader() Attempting startup of OMNIKEY AG CardMan 3121 00 00 using /usr/lib/pcsc/drivers/ifd-ccid.bundle/Contents/Linux/libccid.so
00000402 [139703017170880] readerfactory.c:950:RFBindFunctions() Loading IFD Handler 3.0
00000022 [139703017170880] ifdhandler.c:2025:init_driver() Driver version: 1.4.34
00000736 [139703017170880] ifdhandler.c:2042:init_driver() LogLevel: 0x0003
00000008 [139703017170880] ifdhandler.c:2053:init_driver() DriverOptions: 0x0000
00000238 [139703017170880] ifdhandler.c:2066:init_driver() LogLevel from LIBCCID_ifdLogLevel: 0x000F
00000007 [139703017170880] ifdhandler.c:110:CreateChannelByNameOrChannel() Lun: 0, device: usb:076b/3021:libudev:0:/dev/bus/usb/001/009
00000007 [139703017170880] ccid_usb.c:237:OpenUSBByName() Reader index: 0, Device: usb:076b/3021:libudev:0:/dev/bus/usb/001/009
00000010 [139703017170880] ccid_usb.c:269:OpenUSBByName() interface_number: 0
00000002 [139703017170880] ccid_usb.c:270:OpenUSBByName() usb bus/device: 1/9
00000002 [139703017170880] ccid_usb.c:302:OpenUSBByName() Using: /usr/lib/pcsc/drivers/ifd-ccid.bundle/Contents/Info.plist
00000763 [139703017170880] ccid_usb.c:320:OpenUSBByName() ifdManufacturerString: Ludovic Rousseau (ludovic.rousseau@free.fr)
00000008 [139703017170880] ccid_usb.c:321:OpenUSBByName() ifdProductString: Generic CCID driver
00000003 [139703017170880] 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.
00005817 [139703017170880] ccid_usb.c:406:OpenUSBByName() Try device: 1/9
00000013 [139703017170880] ccid_usb.c:416:OpenUSBByName() vid/pid : 076B/3021
00000005 [139703017170880] ccid_usb.c:482:OpenUSBByName() Checking device: 1/9
00000002 [139703017170880] ccid_usb.c:553:OpenUSBByName() Trying to open USB bus/device: 1/9
00208073 [139703017170880] ccid_usb.c:659:OpenUSBByName() Found Vendor/Product: 076B/3021 (OMNIKEY AG CardMan 3121)
00000017 [139703017170880] ccid_usb.c:661:OpenUSBByName() Using USB bus/device: 1/9
00000006 [139703017170880] ccid_usb.c:1275:ControlUSB() request: 0x03
00015185 [139703017170880] receive: 00 2A 00 00 01 54 00 00 02 A8 00 00 05 50 01 00 0B A0 02 00 16 40 05 00 08 F8 01 00 0D 48 03 00 67 32 00 00 CE 64 00 00 9C C9 00 00 39 93 01 00 73 26 03 00 E7 4C 06 00 D6 5C 02 00 10 F0 03 00 00 1C 00 00 00 38 00 00 01 70 00 00 03 E0 00 00 07 C0 01 00 0E 80 03 00 09 30 02 00 9A 21 00 00 34 43 00 00 68 86 00 00 D1 0C 01 00 A2 19 02 00 44 33 04 00 00 15 00 00 04 FC 00 00 06 A4 01 00 33 19 00 00 6B 2E 01 00 80 1F 00 00 01 3F 00 00 02 7E 00 00 06 7A 01 00 0A 76 02 00 00 0E 00 00 04 18 01 00 CD 10 00 00 80 0A 00 00 03 D2 00 00 99 0C 00 00 35 97 00 00 C0 0F 00 00 03 BD 00 00 05 3B 01 00 66 08 00 00 14 0A 00 00 29 14 00 00 52 28 00 00 A5 50 00 00 4A A1 00 00 94 42 01 00 F7 78 00 00 84 1E 00 00 09 3D 00 00 12 7A 00 00 24 F4 00 00 48 E8 01 00 90 D0 03 00 36 6E 01 00 5A 62 02 00 9F 24 00 00 3E 49 00 00 7C 92 00 00 F8 24 01 00 F0 49 02 00 E0 93 04 00 74 B7 01 00 6C DC 02 00 58 14 00 00 B0 28 00 00 61 51 00 00 C2 A2 00 00 85 45 01 00 0A 8B 02 00 E6 96 01 00 6A 18 00 00 D4 30 00 00 A8 61 00 00 50 C3 00 00 A0 86 01 00 40 0D 03 00 42 0F 00 00 1B B7 00 00 2D 31 01 00 4F 12 00 00 BA DB 00 00 E3 16 00 00 C6 2D 00 00 8D 5B 00 00 A8 12 01 00 C3 C9 01 00 2C 0A 00 00 73 CB 00 00 35 0C 00 00 A1 07 00 00 96 98 00 00 27 09 00 00 DD 6D 00 00 71 0B 00 00 54 89 00 00 E1 E4 00 00 C4 26 00 00 89 4D 00 00 12 9B 00 00 25 36 01 00 38 D1 01 00 D8 19 00 00 B0 33 00 00 61 67 00 00 C3 CE 00 00 87 9D 01 00 62 13 00 00 9C E8 00 00 AF 83 01 00 EC 0C 00 00 74 02 01 00 B1 09 00 00 4E 74 00 00 D7 C1 00 00 C0 07 00 00 81 0F 00 00 03 1F 00 00 07 3E 00 00 0F 7C 00 00 1E F8 00 00 0B 5D 00 00 2A 1C 00 00 55 38 00 00 AB 70 00 00 57 E1 00 00 AF C2 01 00 03 52 01 00 C7 12 00 00 8E 25 00 00 1D 4B 00 00 3A 96 00 00 74 2C 01 00 91 77 01 00 15 0E 00 00 01 A9 00 00 AD 19 01 00 63 09 00 00 C8 BB 00 00 0A 07 00 00 80 54 00 00 D6 8C 00 00 43 AB 01 53 B6 F7 53 AB FE 85 AC 21 30 55 05 30 54 07 A1 C4 20 54 02 A1 C4 EF 33 D2 0A 92 0B 85 21 AC C2 0A 85 21 AC 33 D2 0A 92 0B 85 21 AC C2 0A 85 21 AC 33 D2 0A 92 0B 85 21 AC C2 0A 85 21 AC 33 D2 0A 92 0B 85 21 AC C2 0A 85 21 AC 33 D2 0A 92 0B 85 21 AC C2 0A 85 21 AC 33 D2 0A 92 0B 85 21 AC C2 0A 85 21 AC 33 D2 0A 92 0B 85 21 AC C2 0A 85 21 AC 33 D2 0A 92 0B 85 21 AC C2 0A 85 21 AC 30 55 05 D2 0A 85 21 AC D2 0B 85 21 AC 43 AB 01 43 B6 08 53 AB FE 22 EF 33 C2 0A 92 0B 85 21 AC D2 0A 85 21 AC 33 C2 0A 92 0B 85 21 AC D2 0A 85 21 AC 33 C2 0A 92 0B 85 21 AC D2 0A 85 21 AC 33 C2 0A 92 0B 85 21 AC D2 0A 85 21 AC 33 C2 0A 92 0B 85 21 AC D2 0A 85 21 AC 33 C2 0A 92 0B 85 21 AC D2 0A 85 21 AC 33 C2 0A 92 0B 85 21 AC D2 0A 85 21 AC 33 C2 0A 92 0B 85 21 AC D2 0A 85 21 AC 20 55 05 C2 0A 85 21 AC D2 0B 85 21 AC 43 AB 01 43 B6 08 53 AB FE 22 30 55 05 20 54 07 C1 BB 30 54 02 C1 BB 53 AC FB 43 AC 0C 00 E5 AC 53 AC FB A2 E3 43 AC 0C 92 0F E5 AC 53 AC FB A2 E3 43 AC 0C 92 0E E5 AC 53 AC FB A2 E3 43 AC 0C 92 0D E5 AC 53 AC FB A2 E3 43 AC 0C 92 0C E5 AC 53 AC FB A2 E3 43 AC 0C 92 0B E5 AC 53 AC FB A2 E3 43 AC 0C 92 0A E5 AC 53 AC FB A2 E3 43 AC 0C 92 09 E5 AC A2 E3 92 08 20 55 03 53 AC FB AF 21 22 43 AC 04 53 AC FB 00 E5 AC 43 AC 04 A2 E3 53 AC FB 92 0F E5 
00000030 [139703017170880] ccid_usb.c:1237:get_data_rates() Got 256 data rates but was expecting 106
00000011 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 10752 bps
00000008 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 21505 bps
00000006 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 43010 bps
00000007 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 86021 bps
00000007 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 172043 bps
00000006 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 344086 bps
00000006 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 129032 bps
00000006 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 215053 bps
00000007 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 12903 bps
00000007 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 25806 bps
00000006 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 51612 bps
00000006 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 103225 bps
00000006 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 206451 bps
00000007 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 412903 bps
00000006 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 154838 bps
00000006 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 258064 bps
00000007 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 7168 bps
00000007 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 14336 bps
00000006 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 28673 bps
00000007 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 57347 bps
00000007 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 114695 bps
00000006 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 229390 bps
00000006 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 143369 bps
00000007 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 8602 bps
00000006 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 17204 bps
00000007 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 34408 bps
00000006 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 68817 bps
00000007 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 137634 bps
00000007 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 275268 bps
00000007 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 5376 bps
00000006 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 64516 bps
00000007 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 107526 bps
00000006 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 6451 bps
00000006 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 77419 bps
00000007 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 8064 bps
00000006 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 16129 bps
00000006 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 32258 bps
00000006 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 96774 bps
00000007 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 161290 bps
00000006 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 3584 bps
00000007 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 71684 bps
00000006 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 4301 bps
00000006 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 2688 bps
00000007 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 53763 bps
00000006 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 3225 bps
00000006 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 38709 bps
00000007 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 4032 bps
00000006 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 48387 bps
00000007 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 80645 bps
00000006 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 2150 bps
00000007 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 2580 bps
00000007 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 5161 bps
00000006 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 10322 bps
00000007 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 20645 bps
00000006 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 41290 bps
00000006 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 82580 bps
00000006 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 30967 bps
00000007 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 7812 bps
00000006 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 15625 bps
00000007 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 31250 bps
00000007 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 62500 bps
00000006 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 125000 bps
00000010 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 250000 bps
00000003 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 93750 bps
00000002 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 156250 bps
00000003 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 9375 bps
00000003 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 18750 bps
00000002 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 37500 bps
00000003 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 75000 bps
00000002 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 150000 bps
00000003 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 300000 bps
00000003 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 112500 bps
00000002 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 187500 bps
00000003 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 5208 bps
00000002 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 10416 bps
00000003 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 20833 bps
00000003 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 41666 bps
00000002 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 83333 bps
00000003 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 166666 bps
00000003 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 104166 bps
00000002 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 6250 bps
00000003 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 12500 bps
00000003 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 25000 bps
00000002 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 50000 bps
00000003 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 100000 bps
00000002 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 200000 bps
00000003 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 3906 bps
00000002 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 46875 bps
00000003 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 78125 bps
00000003 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 4687 bps
00000002 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 56250 bps
00000003 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 5859 bps
00000003 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 11718 bps
00000002 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 23437 bps
00000003 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 70312 bps
00000003 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 117187 bps
00000002 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 2604 bps
00000003 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 52083 bps
00000003 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 3125 bps
00000002 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 1953 bps
00000003 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 39062 bps
00000002 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 2343 bps
00000003 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 28125 bps
00000002 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 2929 bps
00000003 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 35156 bps
00000003 [139703017170880] ccid_usb.c:1255:get_data_rates() declared: 58593 bps
00001620 [139703017170880] ccid_usb.c:1328:InterruptRead() before (0), timeout: 100 ms
00005452 [139703017170880] ccid_usb.c:1374:InterruptRead() after (0) (0)
00000029 [139703017170880] NotifySlotChange: 50 03 
00000018 [139703017170880] -> 000000 65 00 00 00 00 00 00 00 00 00 
00000560 [139703017170880] <- 000000 81 00 00 00 00 00 00 01 00 01 
00000018 [139703017170880] -> 000000 65 00 00 00 00 00 01 00 00 00 
00000465 [139703017170880] <- 000000 81 00 00 00 00 00 01 01 00 01 
00000026 [139703017170880] ifdhandler.c:388:IFDHGetCapabilities() tag: 0xFB3, usb:076b/3021:libudev:0:/dev/bus/usb/001/009 (lun: 0)
00000007 [139703017170880] readerfactory.c:396:RFAddReader() Using the reader polling thread
00000007 [139703017170880] ifdhandler.c:1885:IFDHICCPresence() usb:076b/3021:libudev:0:/dev/bus/usb/001/009 (lun: 0)
00000010 [139703017170880] -> 000000 65 00 00 00 00 00 02 00 00 00 
00000593 [139703017170880] <- 000000 81 00 00 00 00 00 02 01 00 01 
00000019 [139703017170880] ifdhandler.c:2005:IFDHICCPresence() Card present
00000197 [139703017170880] ifdhandler.c:388:IFDHGetCapabilities() tag: 0xFAE, usb:076b/3021:libudev:0:/dev/bus/usb/001/009 (lun: 0)
00000015 [139703017170880] ifdhandler.c:484:IFDHGetCapabilities() Reader supports 1 slot(s)
00000042 [139703000380992] ifdhandler.c:1885:IFDHICCPresence() usb:076b/3021:libudev:0:/dev/bus/usb/001/009 (lun: 0)
00000018 [139703000380992] -> 000000 65 00 00 00 00 00 03 00 00 00 
00000575 [139703000380992] <- 000000 81 00 00 00 00 00 03 01 00 01 
00000019 [139703000380992] ifdhandler.c:2005:IFDHICCPresence() Card present
00000013 [139703000380992] ifdhandler.c:1885:IFDHICCPresence() usb:076b/3021:libudev:0:/dev/bus/usb/001/009 (lun: 0)
00000014 [139703000380992] -> 000000 65 00 00 00 00 00 04 00 00 00 
00000191 [139703017170880] hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x413C, PID: 0x2513, path: /dev/bus/usb/001/003
00000228 [139703000380992] <- 000000 81 00 00 00 00 00 04 01 00 01 
00000010 [139703000380992] ifdhandler.c:2005:IFDHICCPresence() Card present
00000006 [139703000380992] ifdhandler.c:1183:IFDHPowerICC() action: PowerUp, usb:076b/3021:libudev:0:/dev/bus/usb/001/009 (lun: 0)
00000009 [139703000380992] -> 000000 62 00 00 00 00 00 05 01 00 00 
00000095 [139703017170880] hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x8087, PID: 0x0020, path: /dev/bus/usb/001/002
00000508 [139703017170880] hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x413C, PID: 0x2513, path: /dev/bus/usb/001/004
00000347 [139703017170880] hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x8087, PID: 0x0020, path: /dev/bus/usb/001/002
00000304 [139703017170880] hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x0461, PID: 0x4DB1, path: /dev/bus/usb/001/005
00000346 [139703017170880] hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x0461, PID: 0x4DB1, path: /dev/bus/usb/001/005
00000413 [139703017170880] hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x8087, PID: 0x0020, path: /dev/bus/usb/001/002
00000828 [139703017170880] hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/003/001
00000860 [139703017170880] hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0003, path: /dev/bus/usb/004/001
00000692 [139703017170880] hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/002/001
00000411 [139703017170880] hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/002/001
00000403 [139703017170880] hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x8087, PID: 0x0020, path: /dev/bus/usb/002/002
00000467 [139703017170880] hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x20A0, PID: 0x42B1, path: /dev/bus/usb/002/003
00000436 [139703017170880] hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x8087, PID: 0x0020, path: /dev/bus/usb/002/002
00000460 [139703017170880] hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x0A5C, PID: 0x5800, path: /dev/bus/usb/002/004
00000021 [139703017170880] hotplug_libudev.c:440:HPAddDevice() Adding USB device: Broadcom Corp 5880
00025806 [139703000380992] <- 000000 80 15 00 00 00 00 05 00 00 00 3B DA 18 FF 81 B1 FE 75 1F 03 00 31 C5 73 C0 01 40 00 90 00 0C 
00000041 [139703000380992] eventhandler.c:289:EHStatusHandlerThread() powerState: POWER_STATE_POWERED
00000017 [139703000380992] Card ATR: 3B DA 18 FF 81 B1 FE 75 1F 03 00 31 C5 73 C0 01 40 00 90 00 0C 
00000013 [139703000380992] ifdhandler.c:1885:IFDHICCPresence() usb:076b/3021:libudev:0:/dev/bus/usb/001/009 (lun: 0)
00000013 [139703000380992] -> 000000 65 00 00 00 00 00 06 00 00 00 
00000548 [139703000380992] <- 000000 81 00 00 00 00 00 06 00 00 00 
00000021 [139703000380992] ifdhandler.c:2005:IFDHICCPresence() Card present
00000021 [139703000380992] ifdhandler.c:317:IFDHPolling() usb:076b/3021:libudev:0:/dev/bus/usb/001/009 (lun: 0) 5000 ms
00000011 [139703000380992] ccid_usb.c:1328:InterruptRead() before (0), timeout: 5000 ms
00000026 [139703017170880] ifdhandler.c:388:IFDHGetCapabilities() tag: 0xFAF, usb:076b/3021:libudev:0:/dev/bus/usb/001/009 (lun: 0)
00000018 [139703017170880] readerfactory.c:726:RFSetReaderName() Support 16 simultaneous readers
00000026 [139703017170880] ifdhandler.c:388:IFDHGetCapabilities() tag: 0xFAD, usb:076b/3021:libudev:0:/dev/bus/usb/001/009 (lun: 0)
00000012 [139703017170880] readerfactory.c:338:RFAddReader() Driver is thread safe
00000010 [139703017170880] readerfactory.c:1074:RFInitializeReader() Attempting startup of Broadcom Corp 5880 [Broadcom USH] (0123456789ABCD) 01 00 using /usr/lib/pcsc/drivers/ifd-ccid.bundle/Contents/Linux/libccid.so
00000009 [139703017170880] readerfactory.c:863:RFLoadReader() Reusing already loaded driver for /usr/lib/pcsc/drivers/ifd-ccid.bundle/Contents/Linux/libccid.so
00000026 [139703017170880] readerfactory.c:950:RFBindFunctions() Loading IFD Handler 3.0
00000046 [139703017170880] ifdhandler.c:110:CreateChannelByNameOrChannel() Lun: 10000, device: usb:0a5c/5800:libudev:0:/dev/bus/usb/002/004
00000017 [139703017170880] ccid_usb.c:237:OpenUSBByName() Reader index: 1, Device: usb:0a5c/5800:libudev:0:/dev/bus/usb/002/004
00000020 [139703017170880] ccid_usb.c:269:OpenUSBByName() interface_number: 0
00000008 [139703017170880] ccid_usb.c:270:OpenUSBByName() usb bus/device: 2/4
00000007 [139703017170880] ccid_usb.c:302:OpenUSBByName() Using: /usr/lib/pcsc/drivers/ifd-ccid.bundle/Contents/Info.plist
00001547 [139703017170880] ccid_usb.c:320:OpenUSBByName() ifdManufacturerString: Ludovic Rousseau (ludovic.rousseau@free.fr)
00000017 [139703017170880] ccid_usb.c:321:OpenUSBByName() ifdProductString: Generic CCID driver
00000006 [139703017170880] 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.
00000411 [139703017170880] ccid_usb.c:406:OpenUSBByName() Try device: 2/4
00000017 [139703017170880] ccid_usb.c:416:OpenUSBByName() vid/pid : 0A5C/5800
00000008 [139703017170880] ccid_usb.c:482:OpenUSBByName() Checking device: 2/4
00000008 [139703017170880] ccid_usb.c:553:OpenUSBByName() Trying to open USB bus/device: 2/4
00142142 [139703017170880] ccid_usb.c:598:OpenUSBByName() Can't get config descriptor on 2/4: LIBUSB_ERROR_NOT_FOUND
00000459 [139703017170880] ccid_usb.c:800:OpenUSBByName() Device not found?
00000013 [139703017170880] ifdhandler.c:155:CreateChannelByNameOrChannel() failed
00000007 [139703017170880] readerfactory.c:1105:RFInitializeReader() Open Port 0x200001 Failed (usb:0a5c/5800:libudev:0:/dev/bus/usb/002/004)
00000005 [139703017170880] readerfactory.c:376:RFAddReader() Broadcom Corp 5880 [Broadcom USH] (0123456789ABCD) init failed.
00000006 [139703017170880] readerfactory.c:610:RFRemoveReader() UnrefReader() count was: 1
00000005 [139703017170880] readerfactory.c:1125:RFUnInitializeReader() Attempting shutdown of Broadcom Corp 5880 [Broadcom USH] (0123456789ABCD) 01 00.
00000406 [139703017170880] hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x8087, PID: 0x0020, path: /dev/bus/usb/002/002
04857112 [139703000380992] ccid_usb.c:1374:InterruptRead() after (0) (2)
00000028 [139703000380992] ifdhandler.c:1885:IFDHICCPresence() usb:076b/3021:libudev:0:/dev/bus/usb/001/009 (lun: 0)
00000021 [139703000380992] -> 000000 65 00 00 00 00 00 07 00 00 00 
00000546 [139703000380992] <- 000000 81 00 00 00 00 00 07 00 00 00 
00000016 [139703000380992] ifdhandler.c:2005:IFDHICCPresence() Card present
00000007 [139703000380992] ifdhandler.c:1183:IFDHPowerICC() action: PowerDown, usb:076b/3021:libudev:0:/dev/bus/usb/001/009 (lun: 0)
00000008 [139703000380992] -> 000000 63 00 00 00 00 00 08 00 00 00 
00000558 [139703000380992] <- 000000 81 00 00 00 00 00 08 01 00 01 
00000018 [139703000380992] eventhandler.c:482:EHStatusHandlerThread() powerState: POWER_STATE_UNPOWERED
00000007 [139703000380992] ifdhandler.c:1885:IFDHICCPresence() usb:076b/3021:libudev:0:/dev/bus/usb/001/009 (lun: 0)
00000008 [139703000380992] -> 000000 65 00 00 00 00 00 09 00 00 00 
00000637 [139703000380992] <- 000000 81 00 00 00 00 00 09 01 00 01 
00000016 [139703000380992] ifdhandler.c:2005:IFDHICCPresence() Card present
00000008 [139703000380992] ifdhandler.c:317:IFDHPolling() usb:076b/3021:libudev:0:/dev/bus/usb/001/009 (lun: 0) 600000 ms
00000005 [139703000380992] ccid_usb.c:1328:InterruptRead() before (0), timeout: 600000 ms
00156455 [139703017170880] winscard_msg_srv.c:256:ProcessEventsServer() Common channel packet arrival
00000027 [139703017170880] winscard_msg_srv.c:267:ProcessEventsServer() ProcessCommonChannelRequest detects: 12
00000006 [139703017170880] pcscdaemon.c:133:SVCServiceRunLoop() A new context thread creation is requested: 12
00000110 [139702983595584] winscard_svc.c:340:ContextThread() Authorized PC/SC client
00000007 [139702983595584] winscard_svc.c:343:ContextThread() Thread is started: dwClientID=12, threadContext @0x55c301d66f10
00000010 [139702983595584] winscard_svc.c:361:ContextThread() Received command: CMD_VERSION from client 12
00000007 [139702983595584] winscard_svc.c:373:ContextThread() Client is protocol version 4:4
00000004 [139702983595584] winscard_svc.c:396:ContextThread() CMD_VERSION rv=0x0 for client 12
00000035 [139702983595584] winscard_svc.c:361:ContextThread() Received command: ESTABLISH_CONTEXT from client 12
00000012 [139702983595584] winscard.c:215:SCardEstablishContext() Establishing Context: 0x4355A976
00000003 [139702983595584] winscard_svc.c:461:ContextThread() ESTABLISH_CONTEXT rv=0x0 for client 12
00000040 [139702983595584] winscard_svc.c:361:ContextThread() Received command: CMD_GET_READERS_STATE from client 12
00000040 [139702983595584] winscard_svc.c:361:ContextThread() Received command: CMD_GET_READERS_STATE from client 12
00000054 [139702983595584] winscard_svc.c:361:ContextThread() Received command: CONNECT from client 12
00000011 [139702983595584] winscard_svc.c:499:ContextThread() Authorized client for 'OMNIKEY AG CardMan 3121 00 00'
00000003 [139702983595584] winscard.c:258:SCardConnect() Attempting Connect to OMNIKEY AG CardMan 3121 00 00 using protocol: 3
00000004 [139702983595584] readerfactory.c:821:RFReaderInfo() RefReader() count was: 1
00000007 [139702983595584] ifdhandler.c:1885:IFDHICCPresence() usb:076b/3021:libudev:0:/dev/bus/usb/001/009 (lun: 0)
00000007 [139702983595584] -> 000000 65 00 00 00 00 00 0A 00 00 00 
00000540 [139702983595584] <- 000000 81 00 00 00 00 00 0A 01 00 01 
00000007 [139702983595584] ifdhandler.c:2005:IFDHICCPresence() Card present
00000007 [139702983595584] ifdhandler.c:1183:IFDHPowerICC() action: PowerUp, usb:076b/3021:libudev:0:/dev/bus/usb/001/009 (lun: 0)
00000006 [139702983595584] -> 000000 62 00 00 00 00 00 0B 01 00 00 
00032355 [139702983595584] <- 000000 80 15 00 00 00 00 0B 00 00 00 3B DA 18 FF 81 B1 FE 75 1F 03 00 31 C5 73 C0 01 40 00 90 00 0C 
00000032 [139702983595584] winscard.c:332:SCardConnect() power up complete.
00000017 [139702983595584] Card ATR: 3B DA 18 FF 81 B1 FE 75 1F 03 00 31 C5 73 C0 01 40 00 90 00 0C 
00000008 [139702983595584] winscard.c:352:SCardConnect() powerState: POWER_STATE_IN_USE
00000008 [139702983595584] prothandler.c:107:PHSetProtocol() Attempting PTS to T=1
00000010 [139702983595584] ifdhandler.c:715:IFDHSetProtocolParameters() protocol T=1, usb:076b/3021:libudev:0:/dev/bus/usb/001/009 (lun: 0)
00000010 [139702983595584] ifdhandler.c:2100:find_baud_rate() Card baud rate: 154838
00000006 [139702983595584] ifdhandler.c:2109:find_baud_rate() Reader can do: 10752
00000006 [139702983595584] ifdhandler.c:2109:find_baud_rate() Reader can do: 21505
00000007 [139702983595584] ifdhandler.c:2109:find_baud_rate() Reader can do: 43010
00000006 [139702983595584] ifdhandler.c:2109:find_baud_rate() Reader can do: 86021
00000006 [139702983595584] ifdhandler.c:2109:find_baud_rate() Reader can do: 172043
00000007 [139702983595584] ifdhandler.c:2109:find_baud_rate() Reader can do: 344086
00000005 [139702983595584] ifdhandler.c:2109:find_baud_rate() Reader can do: 129032
00000006 [139702983595584] ifdhandler.c:2109:find_baud_rate() Reader can do: 215053
00000006 [139702983595584] ifdhandler.c:2109:find_baud_rate() Reader can do: 12903
00000007 [139702983595584] ifdhandler.c:2109:find_baud_rate() Reader can do: 25806
00000006 [139702983595584] ifdhandler.c:2109:find_baud_rate() Reader can do: 51612
00000005 [139702983595584] ifdhandler.c:2109:find_baud_rate() Reader can do: 103225
00000010 [139702983595584] ifdhandler.c:2109:find_baud_rate() Reader can do: 206451
00000004 [139702983595584] ifdhandler.c:2109:find_baud_rate() Reader can do: 412903
00000003 [139702983595584] ifdhandler.c:2109:find_baud_rate() Reader can do: 154838
00000004 [139702983595584] ifdhandler.c:847:IFDHSetProtocolParameters() Set speed to 154838 bauds
00000005 [139702983595584] ifdhandler.c:1008:IFDHSetProtocolParameters() BWI/CWI (TB3) present: 0x75
00000005 [139702983595584] ifdhandler.c:1043:IFDHSetProtocolParameters() IFSC (TA3) present: 254
00000003 [139702983595584] ifdhandler.c:1047:IFDHSetProtocolParameters() Timeout: 11043 ms
00000004 [139702983595584] commands.c:2286:SetParameters() length: 7 bytes
00000008 [139702983595584] -> 000000 61 07 00 00 00 00 0C 01 00 00 18 10 FF 75 00 FE 00 
00008505 [139702983595584] <- 000000 82 07 00 00 00 00 0C 00 00 01 18 10 FF 75 00 FE 00 
00000023 [139702983595584] ifdhandler.c:1104:IFDHSetProtocolParameters() IFSC (TA3) present: 254
00000006 [139702983595584] ifdhandler.c:1117:IFDHSetProtocolParameters() T=1: IFSC=254, IFSD=254
00000006 [139702983595584] winscard.c:430:SCardConnect() Active Protocol: T=1
00000007 [139702983595584] winscard.c:456:SCardConnect() hCard Identity: 686a842b
00000008 [139702983595584] winscard.c:518:SCardConnect() UnrefReader() count was: 2
00000007 [139702983595584] winscard_svc.c:513:ContextThread() CONNECT rv=0x0 for client 12
00000132 [139702983595584] winscard_svc.c:361:ContextThread() Received command: CONTROL from client 12
00000021 [139702983595584] readerfactory.c:848:RFReaderInfoById() RefReader() count was: 1
00000010 [139702983595584] ifdhandler.c:1440:IFDHControl() ControlCode: 0x42000D48, usb:076b/3021:libudev:0:/dev/bus/usb/001/009 (lun: 0)
00000005 [139702983595584] Control TxBuffer: 
00000023 [139702983595584] Control RxBuffer: 12 04 42 33 00 12 
00000012 [139702983595584] winscard.c:1359:SCardControl() UnrefReader() count was: 2
00000006 [139702983595584] winscard_svc.c:735:ContextThread() CONTROL rv=0x0 for client 12
00000093 [139702983595584] winscard_svc.c:361:ContextThread() Received command: CONTROL from client 12
00000020 [139702983595584] readerfactory.c:848:RFReaderInfoById() RefReader() count was: 1
00000009 [139702983595584] ifdhandler.c:1440:IFDHControl() ControlCode: 0x42330012, usb:076b/3021:libudev:0:/dev/bus/usb/001/009 (lun: 0)
00000006 [139702983595584] Control TxBuffer: 
00000015 [139702983595584] Control RxBuffer: 01 02 00 00 03 01 00 09 01 00 0B 02 6B 07 0C 02 21 30 0A 04 00 00 00 00 
00000006 [139702983595584] winscard.c:1359:SCardControl() UnrefReader() count was: 2
00000007 [139702983595584] winscard_svc.c:735:ContextThread() CONTROL rv=0x0 for client 12
00000088 [139702983595584] winscard_svc.c:361:ContextThread() Received command: CMD_GET_READERS_STATE from client 12
00000068 [139702983595584] winscard_svc.c:361:ContextThread() Received command: STATUS from client 12
00000017 [139702983595584] readerfactory.c:848:RFReaderInfoById() RefReader() count was: 1
00000007 [139702983595584] winscard.c:1300:SCardStatus() UnrefReader() count was: 2
00000006 [139702983595584] winscard_svc.c:632:ContextThread() STATUS rv=0x0 for client 12
00000066 [139702983595584] winscard_svc.c:361:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 12
00000014 [139702983595584] winscard_svc.c:834:MSGSendReaderStates() Send reader states: 12
00000052 [139702983595584] winscard_svc.c:361:ContextThread() Received command: CMD_STOP_WAITING_READER_STATE_CHANGE from client 12
00000008 [139702983595584] winscard_svc.c:442:ContextThread() CMD_STOP_WAITING_READER_STATE_CHANGE rv=0x0 for client 12
00000044 [139702983595584] winscard_svc.c:361:ContextThread() Received command: TRANSMIT from client 12
00000018 [139702983595584] readerfactory.c:848:RFReaderInfoById() RefReader() count was: 1
00000006 [139702983595584] winscard.c:1595:SCardTransmit() Send Protocol: T=1
00000004 [139702983595584] APDU: 00 A4 00 0C 02 3F 00 
00000006 [139702983595584] ifdhandler.c:1332:IFDHTransmitToICC() usb:076b/3021:libudev:0:/dev/bus/usb/001/009 (lun: 0)
00000006 [139702983595584] commands.c:1778:CmdXfrBlockTPDU_T0() T=0: 7 bytes
00000007 [139702983595584] -> 000000 6F 07 00 00 00 00 0D 00 00 00 00 A4 00 0C 02 3F 00 
00021987 [139702983595584] <- 000000 80 02 00 00 00 00 0D 00 00 00 6B 00 
00000028 [139702983595584] SW: 6B 00 
00000008 [139702983595584] winscard.c:1640:SCardTransmit() UnrefReader() count was: 2
00000010 [139702983595584] winscard_svc.c:685:ContextThread() TRANSMIT rv=0x0 for client 12
00000138 [139702983595584] winscard_svc.c:361:ContextThread() Received command: TRANSMIT from client 12
00000021 [139702983595584] readerfactory.c:848:RFReaderInfoById() RefReader() count was: 1
00000005 [139702983595584] winscard.c:1595:SCardTransmit() Send Protocol: T=1
00000006 [139702983595584] APDU: 00 A4 04 00 06 D2 76 00 01 24 01 
00000006 [139702983595584] ifdhandler.c:1332:IFDHTransmitToICC() usb:076b/3021:libudev:0:/dev/bus/usb/001/009 (lun: 0)
00000006 [139702983595584] commands.c:1778:CmdXfrBlockTPDU_T0() T=0: 11 bytes
00000008 [139702983595584] -> 000000 6F 0B 00 00 00 00 0E 00 00 00 00 A4 04 00 06 D2 76 00 01 24 01 
00019392 [139702983595584] <- 000000 80 02 00 00 00 00 0E 00 00 00 90 00 
00000019 [139702983595584] SW: 90 00 
00000005 [139702983595584] winscard.c:1640:SCardTransmit() UnrefReader() count was: 2
00000005 [139702983595584] winscard_svc.c:685:ContextThread() TRANSMIT rv=0x0 for client 12
00000080 [139702983595584] winscard_svc.c:361:ContextThread() Received command: TRANSMIT from client 12
00000019 [139702983595584] readerfactory.c:848:RFReaderInfoById() RefReader() count was: 1
00000006 [139702983595584] winscard.c:1595:SCardTransmit() Send Protocol: T=1
00000005 [139702983595584] APDU: 00 CA 00 4F 00 
00000005 [139702983595584] ifdhandler.c:1332:IFDHTransmitToICC() usb:076b/3021:libudev:0:/dev/bus/usb/001/009 (lun: 0)
00000005 [139702983595584] commands.c:1778:CmdXfrBlockTPDU_T0() T=0: 5 bytes
00000007 [139702983595584] -> 000000 6F 05 00 00 00 00 0F 00 00 00 00 CA 00 4F 00 
00012901 [139702983595584] <- 000000 80 12 00 00 00 00 0F 00 00 00 D2 76 00 01 24 01 02 00 00 05 00 00 01 5B 00 00 90 00 
00000035 [139702983595584] SW: D2 76 00 01 24 01 02 00 00 05 00 00 01 5B 00 00 90 00 
00000013 [139702983595584] winscard.c:1640:SCardTransmit() UnrefReader() count was: 2
00000010 [139702983595584] winscard_svc.c:685:ContextThread() TRANSMIT rv=0x0 for client 12
00000144 [139702983595584] winscard_svc.c:361:ContextThread() Received command: TRANSMIT from client 12
00000039 [139702983595584] readerfactory.c:848:RFReaderInfoById() RefReader() count was: 1
00000013 [139702983595584] winscard.c:1595:SCardTransmit() Send Protocol: T=1
00000010 [139702983595584] APDU: 00 CA 5F 52 00 
00000012 [139702983595584] ifdhandler.c:1332:IFDHTransmitToICC() usb:076b/3021:libudev:0:/dev/bus/usb/001/009 (lun: 0)
00000010 [139702983595584] commands.c:1778:CmdXfrBlockTPDU_T0() T=0: 5 bytes
00000018 [139702983595584] -> 000000 6F 05 00 00 00 00 10 00 00 00 00 CA 5F 52 00 
00011505 [139702983595584] <- 000000 80 0C 00 00 00 00 10 00 00 00 00 31 C5 73 C0 01 40 05 90 00 90 00 
00000025 [139702983595584] SW: 00 31 C5 73 C0 01 40 05 90 00 90 00 
00000009 [139702983595584] winscard.c:1640:SCardTransmit() UnrefReader() count was: 2
00000008 [139702983595584] winscard_svc.c:685:ContextThread() TRANSMIT rv=0x0 for client 12
00000110 [139702983595584] winscard_svc.c:361:ContextThread() Received command: TRANSMIT from client 12
00000024 [139702983595584] readerfactory.c:848:RFReaderInfoById() RefReader() count was: 1
00000008 [139702983595584] winscard.c:1595:SCardTransmit() Send Protocol: T=1
00000008 [139702983595584] APDU: 00 CA 00 C4 00 
00000009 [139702983595584] ifdhandler.c:1332:IFDHTransmitToICC() usb:076b/3021:libudev:0:/dev/bus/usb/001/009 (lun: 0)
00000004 [139702983595584] commands.c:1778:CmdXfrBlockTPDU_T0() T=0: 5 bytes
00000007 [139702983595584] -> 000000 6F 05 00 00 00 00 11 00 00 00 00 CA 00 C4 00 
00015801 [139702983595584] <- 000000 80 09 00 00 00 00 11 00 00 00 00 20 20 20 03 00 03 90 00 
00000030 [139702983595584] SW: 00 20 20 20 03 00 03 90 00 
00000009 [139702983595584] winscard.c:1640:SCardTransmit() UnrefReader() count was: 2
00000007 [139702983595584] winscard_svc.c:685:ContextThread() TRANSMIT rv=0x0 for client 12
00000113 [139702983595584] winscard_svc.c:361:ContextThread() Received command: TRANSMIT from client 12
00000039 [139702983595584] readerfactory.c:848:RFReaderInfoById() RefReader() count was: 1
00000011 [139702983595584] winscard.c:1595:SCardTransmit() Send Protocol: T=1
00000010 [139702983595584] APDU: 00 CA 00 6E 00 
00000009 [139702983595584] ifdhandler.c:1332:IFDHTransmitToICC() usb:076b/3021:libudev:0:/dev/bus/usb/001/009 (lun: 0)
00000009 [139702983595584] commands.c:1778:CmdXfrBlockTPDU_T0() T=0: 5 bytes
00000016 [139702983595584] -> 000000 6F 05 00 00 00 00 12 00 00 00 00 CA 00 6E 00 
00084182 [139702983595584] <- 000000 80 DB 00 00 00 00 12 00 00 00 4F 10 D2 76 00 01 24 01 02 00 00 05 00 00 01 5B 00 00 5F 52 0A 00 31 C5 73 C0 01 40 05 90 00 73 81 B7 C0 0A 7C 00 08 00 08 00 08 00 08 00 C1 06 01 10 00 00 20 00 C2 06 01 10 00 00 20 00 C3 06 01 10 00 00 20 00 C4 07 00 20 20 20 03 00 03 C5 3C 41 99 AD 79 95 14 F1 62 4E F3 CE 76 5A 8F 39 C3 1C 32 17 CA A0 F3 06 F8 B1 02 70 25 5E 1B D6 0F 55 3E CF 3A C5 F1 92 B4 B3 13 E5 94 A3 97 DD F2 4B D1 A8 6D DD 8D 36 F0 A7 10 50 2F C6 3C 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 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 CD 0C 60 00 D3 73 5F B9 9F DB 56 53 A1 09 90 00 
00000076 [139702983595584] SW: 4F 10 D2 76 00 01 24 01 02 00 00 05 00 00 01 5B 00 00 5F 52 0A 00 31 C5 73 C0 01 40 05 90 00 73 81 B7 C0 0A 7C 00 08 00 08 00 08 00 08 00 C1 06 01 10 00 00 20 00 C2 06 01 10 00 00 20 00 C3 06 01 10 00 00 20 00 C4 07 00 20 20 20 03 00 03 C5 3C 41 99 AD 79 95 14 F1 62 4E F3 CE 76 5A 8F 39 C3 1C 32 17 CA A0 F3 06 F8 B1 02 70 25 5E 1B D6 0F 55 3E CF 3A C5 F1 92 B4 B3 13 E5 94 A3 97 DD F2 4B D1 A8 6D DD 8D 36 F0 A7 10 50 2F C6 3C 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 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 CD 0C 60 00 D3 73 5F B9 9F DB 56 53 A1 09 90 00 
00000007 [139702983595584] winscard.c:1640:SCardTransmit() UnrefReader() count was: 2
00000008 [139702983595584] winscard_svc.c:685:ContextThread() TRANSMIT rv=0x0 for client 12
00000153 [139702983595584] winscard_svc.c:361:ContextThread() Received command: TRANSMIT from client 12
00000035 [139702983595584] readerfactory.c:848:RFReaderInfoById() RefReader() count was: 1
00000009 [139702983595584] winscard.c:1595:SCardTransmit() Send Protocol: T=1
00000008 [139702983595584] APDU: 00 CA 7F 74 00 
00000008 [139702983595584] ifdhandler.c:1332:IFDHTransmitToICC() usb:076b/3021:libudev:0:/dev/bus/usb/001/009 (lun: 0)
00000007 [139702983595584] commands.c:1778:CmdXfrBlockTPDU_T0() T=0: 5 bytes
00000013 [139702983595584] -> 000000 6F 05 00 00 00 00 13 00 00 00 00 CA 7F 74 00 
00010471 [139702983595584] <- 000000 80 02 00 00 00 00 13 00 00 00 6A 88 
00000024 [139702983595584] SW: 6A 88 
00000010 [139702983595584] winscard.c:1640:SCardTransmit() UnrefReader() count was: 2
00000008 [139702983595584] winscard_svc.c:685:ContextThread() TRANSMIT rv=0x0 for client 12
00000119 [139702983595584] winscard_svc.c:361:ContextThread() Received command: TRANSMIT from client 12
00000031 [139702983595584] readerfactory.c:848:RFReaderInfoById() RefReader() count was: 1
00000007 [139702983595584] winscard.c:1595:SCardTransmit() Send Protocol: T=1
00000007 [139702983595584] APDU: 00 CA 00 5E 00 
00000008 [139702983595584] ifdhandler.c:1332:IFDHTransmitToICC() usb:076b/3021:libudev:0:/dev/bus/usb/001/009 (lun: 0)
00000011 [139702983595584] commands.c:1778:CmdXfrBlockTPDU_T0() T=0: 5 bytes
00000013 [139702983595584] -> 000000 6F 05 00 00 00 00 14 00 00 00 00 CA 00 5E 00 
00012669 [139702983595584] <- 000000 80 17 00 00 00 00 14 00 00 00 64 61 6E 69 65 6C 40 6D 61 6B 72 6F 74 6F 70 69 61 2E 6F 72 67 90 00 
00000036 [139702983595584] SW: 64 61 6E 69 65 6C 40 6D 61 6B 72 6F 74 6F 70 69 61 2E 6F 72 67 90 00 
00000009 [139702983595584] winscard.c:1640:SCardTransmit() UnrefReader() count was: 2
00000008 [139702983595584] winscard_svc.c:685:ContextThread() TRANSMIT rv=0x0 for client 12
00000137 [139702983595584] winscard_svc.c:361:ContextThread() Received command: TRANSMIT from client 12
00000044 [139702983595584] readerfactory.c:848:RFReaderInfoById() RefReader() count was: 1
00000012 [139702983595584] winscard.c:1595:SCardTransmit() Send Protocol: T=1
00000009 [139702983595584] APDU: 00 CA 00 6E 00 
00000010 [139702983595584] ifdhandler.c:1332:IFDHTransmitToICC() usb:076b/3021:libudev:0:/dev/bus/usb/001/009 (lun: 0)
00000008 [139702983595584] commands.c:1778:CmdXfrBlockTPDU_T0() T=0: 5 bytes
00000016 [139702983595584] -> 000000 6F 05 00 00 00 00 15 00 00 00 00 CA 00 6E 00 
00083981 [139702983595584] <- 000000 80 DB 00 00 00 00 15 00 00 00 4F 10 D2 76 00 01 24 01 02 00 00 05 00 00 01 5B 00 00 5F 52 0A 00 31 C5 73 C0 01 40 05 90 00 73 81 B7 C0 0A 7C 00 08 00 08 00 08 00 08 00 C1 06 01 10 00 00 20 00 C2 06 01 10 00 00 20 00 C3 06 01 10 00 00 20 00 C4 07 00 20 20 20 03 00 03 C5 3C 41 99 AD 79 95 14 F1 62 4E F3 CE 76 5A 8F 39 C3 1C 32 17 CA A0 F3 06 F8 B1 02 70 25 5E 1B D6 0F 55 3E CF 3A C5 F1 92 B4 B3 13 E5 94 A3 97 DD F2 4B D1 A8 6D DD 8D 36 F0 A7 10 50 2F C6 3C 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 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 CD 0C 60 00 D3 73 5F B9 9F DB 56 53 A1 09 90 00 
00000090 [139702983595584] SW: 4F 10 D2 76 00 01 24 01 02 00 00 05 00 00 01 5B 00 00 5F 52 0A 00 31 C5 73 C0 01 40 05 90 00 73 81 B7 C0 0A 7C 00 08 00 08 00 08 00 08 00 C1 06 01 10 00 00 20 00 C2 06 01 10 00 00 20 00 C3 06 01 10 00 00 20 00 C4 07 00 20 20 20 03 00 03 C5 3C 41 99 AD 79 95 14 F1 62 4E F3 CE 76 5A 8F 39 C3 1C 32 17 CA A0 F3 06 F8 B1 02 70 25 5E 1B D6 0F 55 3E CF 3A C5 F1 92 B4 B3 13 E5 94 A3 97 DD F2 4B D1 A8 6D DD 8D 36 F0 A7 10 50 2F C6 3C 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 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 CD 0C 60 00 D3 73 5F B9 9F DB 56 53 A1 09 90 00 
00000008 [139702983595584] winscard.c:1640:SCardTransmit() UnrefReader() count was: 2
00000009 [139702983595584] winscard_svc.c:685:ContextThread() TRANSMIT rv=0x0 for client 12
00000151 [139702983595584] winscard_svc.c:361:ContextThread() Received command: TRANSMIT from client 12
00000024 [139702983595584] readerfactory.c:848:RFReaderInfoById() RefReader() count was: 1
00000007 [139702983595584] winscard.c:1595:SCardTransmit() Send Protocol: T=1
00000008 [139702983595584] APDU: 00 CA 00 6E 00 
00000009 [139702983595584] ifdhandler.c:1332:IFDHTransmitToICC() usb:076b/3021:libudev:0:/dev/bus/usb/001/009 (lun: 0)
00000008 [139702983595584] commands.c:1778:CmdXfrBlockTPDU_T0() T=0: 5 bytes
00000014 [139702983595584] -> 000000 6F 05 00 00 00 00 16 00 00 00 00 CA 00 6E 00 
00084072 [139702983595584] <- 000000 80 DB 00 00 00 00 16 00 00 00 4F 10 D2 76 00 01 24 01 02 00 00 05 00 00 01 5B 00 00 5F 52 0A 00 31 C5 73 C0 01 40 05 90 00 73 81 B7 C0 0A 7C 00 08 00 08 00 08 00 08 00 C1 06 01 10 00 00 20 00 C2 06 01 10 00 00 20 00 C3 06 01 10 00 00 20 00 C4 07 00 20 20 20 03 00 03 C5 3C 41 99 AD 79 95 14 F1 62 4E F3 CE 76 5A 8F 39 C3 1C 32 17 CA A0 F3 06 F8 B1 02 70 25 5E 1B D6 0F 55 3E CF 3A C5 F1 92 B4 B3 13 E5 94 A3 97 DD F2 4B D1 A8 6D DD 8D 36 F0 A7 10 50 2F C6 3C 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 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 CD 0C 60 00 D3 73 5F B9 9F DB 56 53 A1 09 90 00 
00000089 [139702983595584] SW: 4F 10 D2 76 00 01 24 01 02 00 00 05 00 00 01 5B 00 00 5F 52 0A 00 31 C5 73 C0 01 40 05 90 00 73 81 B7 C0 0A 7C 00 08 00 08 00 08 00 08 00 C1 06 01 10 00 00 20 00 C2 06 01 10 00 00 20 00 C3 06 01 10 00 00 20 00 C4 07 00 20 20 20 03 00 03 C5 3C 41 99 AD 79 95 14 F1 62 4E F3 CE 76 5A 8F 39 C3 1C 32 17 CA A0 F3 06 F8 B1 02 70 25 5E 1B D6 0F 55 3E CF 3A C5 F1 92 B4 B3 13 E5 94 A3 97 DD F2 4B D1 A8 6D DD 8D 36 F0 A7 10 50 2F C6 3C 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 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 CD 0C 60 00 D3 73 5F B9 9F DB 56 53 A1 09 90 00 
00000013 [139702983595584] winscard.c:1640:SCardTransmit() UnrefReader() count was: 2
00000011 [139702983595584] winscard_svc.c:685:ContextThread() TRANSMIT rv=0x0 for client 12
00000102 [139702983595584] winscard_svc.c:361:ContextThread() Received command: TRANSMIT from client 12
00000025 [139702983595584] readerfactory.c:848:RFReaderInfoById() RefReader() count was: 1
00000007 [139702983595584] winscard.c:1595:SCardTransmit() Send Protocol: T=1
00000007 [139702983595584] APDU: 00 CA 00 6E 00 
00000009 [139702983595584] ifdhandler.c:1332:IFDHTransmitToICC() usb:076b/3021:libudev:0:/dev/bus/usb/001/009 (lun: 0)
00000007 [139702983595584] commands.c:1778:CmdXfrBlockTPDU_T0() T=0: 5 bytes
00000010 [139702983595584] -> 000000 6F 05 00 00 00 00 17 00 00 00 00 CA 00 6E 00 
00084115 [139702983595584] <- 000000 80 DB 00 00 00 00 17 00 00 00 4F 10 D2 76 00 01 24 01 02 00 00 05 00 00 01 5B 00 00 5F 52 0A 00 31 C5 73 C0 01 40 05 90 00 73 81 B7 C0 0A 7C 00 08 00 08 00 08 00 08 00 C1 06 01 10 00 00 20 00 C2 06 01 10 00 00 20 00 C3 06 01 10 00 00 20 00 C4 07 00 20 20 20 03 00 03 C5 3C 41 99 AD 79 95 14 F1 62 4E F3 CE 76 5A 8F 39 C3 1C 32 17 CA A0 F3 06 F8 B1 02 70 25 5E 1B D6 0F 55 3E CF 3A C5 F1 92 B4 B3 13 E5 94 A3 97 DD F2 4B D1 A8 6D DD 8D 36 F0 A7 10 50 2F C6 3C 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 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 CD 0C 60 00 D3 73 5F B9 9F DB 56 53 A1 09 90 00 
00000120 [139702983595584] SW: 4F 10 D2 76 00 01 24 01 02 00 00 05 00 00 01 5B 00 00 5F 52 0A 00 31 C5 73 C0 01 40 05 90 00 73 81 B7 C0 0A 7C 00 08 00 08 00 08 00 08 00 C1 06 01 10 00 00 20 00 C2 06 01 10 00 00 20 00 C3 06 01 10 00 00 20 00 C4 07 00 20 20 20 03 00 03 C5 3C 41 99 AD 79 95 14 F1 62 4E F3 CE 76 5A 8F 39 C3 1C 32 17 CA A0 F3 06 F8 B1 02 70 25 5E 1B D6 0F 55 3E CF 3A C5 F1 92 B4 B3 13 E5 94 A3 97 DD F2 4B D1 A8 6D DD 8D 36 F0 A7 10 50 2F C6 3C 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 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 CD 0C 60 00 D3 73 5F B9 9F DB 56 53 A1 09 90 00 
00000015 [139702983595584] winscard.c:1640:SCardTransmit() UnrefReader() count was: 2
00000010 [139702983595584] winscard_svc.c:685:ContextThread() TRANSMIT rv=0x0 for client 12
00000204 [139702983595584] winscard_svc.c:361:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 12
00000023 [139702983595584] winscard_svc.c:834:MSGSendReaderStates() Send reader states: 12
00001160 [139702983595584] winscard_svc.c:361:ContextThread() Received command: CMD_STOP_WAITING_READER_STATE_CHANGE from client 12
00000024 [139702983595584] winscard_svc.c:442:ContextThread() CMD_STOP_WAITING_READER_STATE_CHANGE rv=0x0 for client 12
00000161 [139702983595584] winscard_svc.c:361:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 12
00000021 [139702983595584] winscard_svc.c:834:MSGSendReaderStates() Send reader states: 12
00000178 [139702983595584] winscard_svc.c:361:ContextThread() Received command: CMD_STOP_WAITING_READER_STATE_CHANGE from client 12
00000024 [139702983595584] winscard_svc.c:442:ContextThread() CMD_STOP_WAITING_READER_STATE_CHANGE rv=0x0 for client 12
00000620 [139702983595584] winscard_svc.c:361:ContextThread() Received command: TRANSMIT from client 12
00000037 [139702983595584] readerfactory.c:848:RFReaderInfoById() RefReader() count was: 1
00000010 [139702983595584] winscard.c:1595:SCardTransmit() Send Protocol: T=1
00000013 [139702983595584] APDU: 00 47 81 00 00 00 02 B6 00 02 0F 
00000010 [139702983595584] ifdhandler.c:1332:IFDHTransmitToICC() usb:076b/3021:libudev:0:/dev/bus/usb/001/009 (lun: 0)
00000008 [139702983595584] commands.c:1778:CmdXfrBlockTPDU_T0() T=0: 11 bytes
00000019 [139702983595584] -> 000000 6F 0B 00 00 00 00 18 00 00 00 00 47 81 00 00 00 02 B6 00 02 0F 
00000674 [139702983595584] <- 000000 80 00 00 00 00 00 18 40 F6 00 
00000019 [139702983595584] commands.c:1539:CCID_Receive Protocol not supported
00000016 [139702983595584] SW: 
00000007 [139702983595584] ifdwrapper.c:543:IFDTransmit() Card not transacted: 612
00000006 [139702983595584] winscard.c:1620:SCardTransmit() Card not transacted: 0x80100016
00000005 [139702983595584] winscard.c:1640:SCardTransmit() UnrefReader() count was: 2
00000006 [139702983595584] winscard_svc.c:685:ContextThread() TRANSMIT rv=0x80100016 for client 12
00000188 [139702983595584] winscard_svc.c:361:ContextThread() Received command: TRANSMIT from client 12
00000025 [139702983595584] readerfactory.c:848:RFReaderInfoById() RefReader() count was: 1
00000005 [139702983595584] winscard.c:1595:SCardTransmit() Send Protocol: T=1
00000006 [139702983595584] APDU: 00 47 81 00 00 00 02 B8 00 02 0F 
00000005 [139702983595584] ifdhandler.c:1332:IFDHTransmitToICC() usb:076b/3021:libudev:0:/dev/bus/usb/001/009 (lun: 0)
00000005 [139702983595584] commands.c:1778:CmdXfrBlockTPDU_T0() T=0: 11 bytes
00000008 [139702983595584] -> 000000 6F 0B 00 00 00 00 19 00 00 00 00 47 81 00 00 00 02 B8 00 02 0F 
00000778 [139702983595584] <- 000000 80 00 00 00 00 00 19 40 F6 00 
00000018 [139702983595584] commands.c:1539:CCID_Receive Protocol not supported
00000005 [139702983595584] SW: 
00000006 [139702983595584] ifdwrapper.c:543:IFDTransmit() Card not transacted: 612
00000005 [139702983595584] winscard.c:1620:SCardTransmit() Card not transacted: 0x80100016
00000005 [139702983595584] winscard.c:1640:SCardTransmit() UnrefReader() count was: 2
00000006 [139702983595584] winscard_svc.c:685:ContextThread() TRANSMIT rv=0x80100016 for client 12
00000223 [139702983595584] winscard_svc.c:361:ContextThread() Received command: TRANSMIT from client 12
00000022 [139702983595584] readerfactory.c:848:RFReaderInfoById() RefReader() count was: 1
00000006 [139702983595584] winscard.c:1595:SCardTransmit() Send Protocol: T=1
00000007 [139702983595584] APDU: 00 47 81 00 00 00 02 A4 00 02 0F 
00000008 [139702983595584] ifdhandler.c:1332:IFDHTransmitToICC() usb:076b/3021:libudev:0:/dev/bus/usb/001/009 (lun: 0)
00000007 [139702983595584] commands.c:1778:CmdXfrBlockTPDU_T0() T=0: 11 bytes
00000017 [139702983595584] -> 000000 6F 0B 00 00 00 00 1A 00 00 00 00 47 81 00 00 00 02 A4 00 02 0F 
00000731 [139702983595584] <- 000000 80 00 00 00 00 00 1A 40 F6 00 
00000046 [139702983595584] commands.c:1539:CCID_Receive Protocol not supported
00000006 [139702983595584] SW: 
00000005 [139702983595584] ifdwrapper.c:543:IFDTransmit() Card not transacted: 612
00000006 [139702983595584] winscard.c:1620:SCardTransmit() Card not transacted: 0x80100016
00000005 [139702983595584] winscard.c:1640:SCardTransmit() UnrefReader() count was: 2
00000009 [139702983595584] winscard_svc.c:685:ContextThread() TRANSMIT rv=0x80100016 for client 12
00000267 [139702983595584] winscard_svc.c:361:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 12
00000008 [139702983595584] winscard_svc.c:834:MSGSendReaderStates() Send reader states: 12
00000044 [139702983595584] winscard_svc.c:361:ContextThread() Received command: CMD_STOP_WAITING_READER_STATE_CHANGE from client 12
00000006 [139702983595584] winscard_svc.c:442:ContextThread() CMD_STOP_WAITING_READER_STATE_CHANGE rv=0x0 for client 12
00000281 [139702983595584] winscard_svc.c:361:ContextThread() Received command: DISCONNECT from client 12
00000021 [139702983595584] readerfactory.c:848:RFReaderInfoById() RefReader() count was: 1
00000010 [139702983595584] winscard.c:881:SCardDisconnect() Active Contexts: -1
00000008 [139702983595584] winscard.c:882:SCardDisconnect() dwDisposition: 0
00000009 [139702983595584] winscard.c:1017:SCardDisconnect() powerState: POWER_STATE_GRACE_PERIOD
00000011 [139702983595584] ifdhandler.c:388:IFDHGetCapabilities() tag: 0xFB2, usb:076b/3021:libudev:0:/dev/bus/usb/001/009 (lun: 0)
00000003 [139702983595584] winscard.c:1030:SCardDisconnect() Stopping polling thread
00000003 [139702983595584] ifdhandler.c:353:IFDHStopPolling() usb:076b/3021:libudev:0:/dev/bus/usb/001/009 (lun: 0)
00002184 [139702983595584] winscard.c:1043:SCardDisconnect() UnrefReader() count was: 2
00000015 [139703000380992] ccid_usb.c:1374:InterruptRead() after (0) (3)
00000006 [139703000380992] ccid_usb.c:1387:InterruptRead() InterruptRead (1/9): 3
00000007 [139702983595584] winscard_svc.c:550:ContextThread() DISCONNECT rv=0x0 for client 12
00000178 [139702983595584] winscard_svc.c:361:ContextThread() Received command: RELEASE_CONTEXT from client 12
00000016 [139702983595584] winscard.c:229:SCardReleaseContext() Releasing Context: 0x4355A976
00000005 [139702983595584] winscard_svc.c:476:ContextThread() RELEASE_CONTEXT rv=0x0 for client 12
00000051 [139702983595584] winscard_svc.c:354:ContextThread() Client die: 12
00000029 [139702983595584] winscard_svc.c:1055:MSGCleanupClient() Thread is stopping: dwClientID=12, threadContext @0x55c301d66f10
00000007 [139702983595584] winscard_svc.c:1063:MSGCleanupClient() Freeing SCONTEXT @0x55c301d66f10
00399866 [139703000380992] eventhandler.c:494:EHStatusHandlerThread() powerState: POWER_STATE_POWERED
00000025 [139703000380992] ifdhandler.c:1885:IFDHICCPresence() usb:076b/3021:libudev:0:/dev/bus/usb/001/009 (lun: 0)
00000012 [139703000380992] -> 000000 65 00 00 00 00 00 1B 00 00 00 
00000615 [139703000380992] <- 000000 81 00 00 00 00 00 1B 00 00 00 
00000018 [139703000380992] ifdhandler.c:2005:IFDHICCPresence() Card present
00000009 [139703000380992] ifdhandler.c:317:IFDHPolling() usb:076b/3021:libudev:0:/dev/bus/usb/001/009 (lun: 0) 5000 ms
00000006 [139703000380992] ccid_usb.c:1328:InterruptRead() before (0), timeout: 5000 ms
05002298 [139703000380992] ccid_usb.c:1374:InterruptRead() after (0) (2)
00000025 [139703000380992] ifdhandler.c:1885:IFDHICCPresence() usb:076b/3021:libudev:0:/dev/bus/usb/001/009 (lun: 0)
00000013 [139703000380992] -> 000000 65 00 00 00 00 00 1C 00 00 00 
00000662 [139703000380992] <- 000000 81 00 00 00 00 00 1C 00 00 00 
00000016 [139703000380992] ifdhandler.c:2005:IFDHICCPresence() Card present
00000007 [139703000380992] ifdhandler.c:1183:IFDHPowerICC() action: PowerDown, usb:076b/3021:libudev:0:/dev/bus/usb/001/009 (lun: 0)
00000008 [139703000380992] -> 000000 63 00 00 00 00 00 1D 00 00 00 
00000520 [139703000380992] <- 000000 81 00 00 00 00 00 1D 01 00 01 
00000015 [139703000380992] eventhandler.c:482:EHStatusHandlerThread() powerState: POWER_STATE_UNPOWERED
00000007 [139703000380992] ifdhandler.c:1885:IFDHICCPresence() usb:076b/3021:libudev:0:/dev/bus/usb/001/009 (lun: 0)
00000008 [139703000380992] -> 000000 65 00 00 00 00 00 1E 00 00 00 
00000523 [139703000380992] <- 000000 81 00 00 00 00 00 1E 01 00 01 
00000019 [139703000380992] ifdhandler.c:2005:IFDHICCPresence() Card present
00000009 [139703000380992] ifdhandler.c:317:IFDHPolling() usb:076b/3021:libudev:0:/dev/bus/usb/001/009 (lun: 0) 600000 ms
00000006 [139703000380992] ccid_usb.c:1328:InterruptRead() before (0), timeout: 600000 ms
dangowrt commented 3 years ago

Just to avoid confusion: never mind that Broadcom 5800 device which is also present, it's the internal reader of the laptop which used to work and then stopped (not related to any updates, it also doesn't respond to vendor firmware update tool in DOS, so I assume the hardware is gone). I'm using the external CardMan reader which works fine with the proprietary driver.

LudovicRousseau commented 3 years ago

The APDU "00 47 81 00 00 00 02 B8 00 02 0F" is problematic and very strange for me. The reader answer with the error "Protocol not supported". I suggest to report the problem on the OpenSC mailing list.

dangowrt commented 3 years ago

The odd thing here is that it does work fine when using the proprietary driver (ifdokccid.so) instead of ccid. See log

00000011 [140114547267136] APDU: 00 47 81 00 00 00 02 B8 00 20 00 
00166482 [140114547267136] SW: 7F 49 82 02 0A 81 82 02 00 9C CD 13 B8 EA 86 04 A3 90 78 58 CB 7B 0B 9A F8 E5 1A 06 4C DF E7 59 4F 7D BC 9F CC A7 CC 60 F2 FB E7 F6 7A 04 E6 DE CA CF D6 BB CE D3 42 17 86 FC CD B7 18 93 B3 BD 26 06 C7 43 F9 28 60 05 27 19 31 03 BB A6 BE 3B FA C4 D0 23 9D 60 CA 4F 86 EA 71 C4 6F 5D DC F6 25 91 F2 97 ED 74 84 52 76 90 C5 93 2A 6F 0A EE C6 76 3D 25 0C D8 C4 6F FC 39 DE 34 A9 E9 B0 FA 86 27 B3 B1 EA C5 61 C0 FF B5 4F 8C 2C 32 61 58 4C 75 28 6F 9A CE 0C 5F F1 F5 B2 59 46 A8 7F 81 55 93 02 69 B8 24 40 99 38 3D 7A CF 53 0E 7E C8 44 B8 67 F4 56 5B CB 81 5A 3A DD 44 38 7C 37 41 1E B2 7D B0 12 01 1B 1D F1 C6 ED 9D 2B 86 0F A4 43 19 CC E1 5A 7D 6E 46 DF 3D 29 B7 95 8E 56 45 29 4E CD 7A F1 49 2A B9 67 05 B1 AF 4C 5C 75 9A D9 27 F5 6C 12 8B EE 21 A7 1C 55 AC 24 E5 9C A3 E8 99 9D 14 2F 88 1C FA 4F 9F 07 55 F6 3B 70 9E AE F9 FE 47 5D F0 C5 EE E6 D3 D7 35 32 64 10 06 9A 39 B0 35 E3 A5 17 79 F0 EB 76 87 D5 CD F2 30 F5 A4 35 F5 ED 2F 1D BF 89 E3 DA 72 23 EF 3E 33 5B A7 69 C2 28 B6 3E 62 EC 33 CD 2F 8B B3 4D 39 E5 73 52 41 0C D3 0C 49 AF 36 87 4A 9C 56 1E 49 19 FB 0A 17 DE 2B 97 57 0D 89 B1 9B 61 3B 09 D3 52 2F 13 CE F5 4B 76 61 DD EA 1D C7 93 95 E5 29 1C 3B 4D E0 C1 58 8A EF FB DD E1 FE 13 D3 06 AA 1B 38 46 12 99 59 F3 F4 08 F8 87 1F 57 27 2F 12 80 B6 B7 0B F8 F4 0B C0 7D C0 D1 D4 4C A5 61 A9 7F 82 4C C8 AB CF 80 E7 7F E2 3D FB 7B 30 58 4E F0 2E A7 41 FA 86 41 EF A3 5F D5 79 A5 7A 90 F6 47 E4 79 F6 1E 8C 3D 33 B3 D3 49 C6 3C 82 02 33 00 EE 0B C5 93 CF CF F5 9D C2 4F 2A 6A 87 76 A7 DE 3C 8C 76 AB 50 8A D0 9C E9 65 74 BA 9D B0 99 B9 E7 99 5D C6 6F D6 45 67 82 04 00 01 00 01 90 00 
LudovicRousseau commented 3 years ago

This is an extended APDU https://ccid.apdu.fr/ccid_extended_apdu.html

Your "OMNIKEY AG CardMan 3121" reader declares it does NOT support extended APDU but short APDU only. https://ccid.apdu.fr/ccid/readers/CardMan3121.txt

I guess the proprietary driver uses proprietary commands to switch the reader to extended APDU mode or something like that. I don't think I can fix your problem in my driver. You should use a reader with extended APDU support.

dangowrt commented 3 years ago

The reader does support TPDU when using the proprietary pcsc driver, as mentioned above. If I can help with USB traces and/or reverse-engineering TPDU_T1R_Handle_R_Block function, let me know.

LudovicRousseau commented 3 years ago

I don't have time and motivation to add support of non-compliant readers. Sorry.