Is it normal for a Gooze Feitan ePass PKI Token to take over 60 seconds to initialize when used with PKCS#11?
I've tracked down the wait to pcscd, and have logs attached. In the logs I've annotated several lines with five asterisks *****. You can see that during the initialization process there is an (exactly) 60 second wait between commands transmitted to the USB token. The command I used to show case this is: $ pkcs11-tool --module ./src/pkcs11/.libs/opensc-pkcs11.so --list-token-slots However any application using the PKCS#11 module (including p11-kit) also generate this issue. This wait corresponds to the below call stack in the opensc PKCS#11 module. This is opensc git master, but the same problem occurs with 0.12.1 as well. This is something that others (Phillip for example) have experienced as well. Any ideas? Cheers, Stef 22 __select_nocancel() /usr/src/debug/glibc-2.14-34-ge2a3090/sysdeps/unix/syscall-template.S:82 0x0000003763ad91d3 21 <symbol is not available> 0x0000003764206cd9 20 SCardTransmit() 0x00000037642041bf 19 pcsc_internal_transmit() /data/projects/opensc/src/libopensc/reader-pcsc.c:188 0x00007ffff7cbb26e 18 pcsc_transmit() /data/projects/opensc/src/libopensc/reader-pcsc.c:246 0x00007ffff7cbb4f7 17 do_single_transmit() /data/projects/opensc/src/libopensc/apdu.c:394 0x00007ffff7c9f667 16 sc_transmit_apdu() /data/projects/opensc/src/libopensc/apdu.c:603 0x00007ffff7c9fe2a 15 entersafe_transmit_apdu() /data/projects/opensc/src/libopensc/card-entersafe.c:360 0x00007ffff7cf447d 14 entersafe_read_binary() /data/projects/opensc/src/libopensc/card-entersafe.c:390 0x00007ffff7cf4670 13 sc_read_binary() /data/projects/opensc/src/libopensc/card.c:454 0x00007ffff7c945ce 12 sc_read_binary() /data/projects/opensc/src/libopensc/card.c:437 0x00007ffff7c943b6 11 sc_pkcs15_read_file() /data/projects/opensc/src/libopensc/pkcs15.c:1930 0x00007ffff7ca61fc 10 sc_pkcs15_parse_df() /data/projects/opensc/src/libopensc/pkcs15.c:1636 0x00007ffff7ca52db 9 __sc_pkcs15_search_objects() /data/projects/opensc/src/libopensc/pkcs15.c:1023 0x00007ffff7ca3cb2 8 sc_pkcs15_get_objects_cond() /data/projects/opensc/src/libopensc/pkcs15.c:1247 0x00007ffff7ca4461 7 sc_pkcs15_get_objects() /data/projects/opensc/src/libopensc/pkcs15.c:1054 0x00007ffff7ca3de2 6 pkcs15_create_pkcs11_objects() /data/projects/opensc/src/pkcs11/framework-pkcs15.c:572 0x00007ffff7a2fb9e 5 pkcs15_create_tokens() /data/projects/opensc/src/pkcs11/framework-pkcs15.c:931 0x00007ffff7a30af5 4 card_detect() /data/projects/opensc/src/pkcs11/slot.c:255 0x00007ffff7a2c64f 3 initialize_reader() /data/projects/opensc/src/pkcs11/slot.c:132 0x00007ffff7a2c0eb 2 C_Initialize() /data/projects/opensc/src/pkcs11/pkcs11-global.c:248 0x00007ffff7a26f14 1 main() /data/projects/opensc/src/tools/pkcs11-tool.c:594 0x0000000000402ffa
Sep 21 09:30:40 stef pcscd: debuglog.c:277:DebugLogSetLevel() debug level=debug Sep 21 09:30:40 stef pcscd: configfile.l:245:DBGetReaderListDir() Parsing conf directory: /etc/reader.conf.d Sep 21 09:30:40 stef pcscd: configfile.l:287:DBGetReaderList() Parsing conf file: /etc/reader.conf.d/libccidtwin Sep 21 09:30:40 stef pcscd: pcscdaemon.c:550:main() pcsc-lite 1.7.2 daemon ready. Sep 21 09:30:40 stef pcscd: hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0001, path: /dev/bus/usb/002/001 Sep 21 09:30:40 stef pcscd: hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0001, path: /dev/bus/usb/002/001 Sep 21 09:30:40 stef pcscd: hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x045E, PID: 0x0040, path: /dev/bus/usb/002/002 Sep 21 09:30:40 stef pcscd: hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0001, path: /dev/bus/usb/003/001 Sep 21 09:30:40 stef pcscd: hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0001, path: /dev/bus/usb/003/001 Sep 21 09:30:40 stef pcscd: hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x045E, PID: 0x00DD, path: /dev/bus/usb/003/002 Sep 21 09:30:40 stef pcscd: hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x045E, PID: 0x00DD, path: /dev/bus/usb/003/002 Sep 21 09:30:40 stef pcscd: hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0001, path: /dev/bus/usb/004/001 Sep 21 09:30:40 stef pcscd: hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0001, path: /dev/bus/usb/005/001 Sep 21 09:30:40 stef pcscd: hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/001/001 Sep 21 09:30:40 stef pcscd: hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/001/001 Sep 21 09:30:40 stef pcscd: hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x0424, PID: 0x2504, path: /dev/bus/usb/001/004 Sep 21 09:30:40 stef pcscd: hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x096E, PID: 0x0503, path: /dev/bus/usb/001/005 Sep 21 09:30:40 stef pcscd: hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x096E, PID: 0x0503, path: /dev/bus/usb/001/005 Sep 21 09:30:40 stef pcscd: hotplug_libudev.c:309:HPAddDevice() Adding USB device: Feitian SCR301 Sep 21 09:30:40 stef pcscd: readerfactory.c:934:RFInitializeReader() Attempting startup of Feitian SCR301 00 00 using /usr/lib64/pcsc/drivers/ifd-ccid.bundle/Contents/Linux/libccid.so Sep 21 09:30:40 stef pcscd: readerfactory.c:824:RFBindFunctions() Loading IFD Handler 3.0 Sep 21 09:30:40 stef pcscd: ifdhandler.c:1732:init_driver() Driver version: 1.4.3 Sep 21 09:30:40 stef pcscd: ifdhandler.c:1750:init_driver() LogLevel: 0x0003 Sep 21 09:30:40 stef pcscd: ifdhandler.c:1771:init_driver() DriverOptions: 0x0000 Sep 21 09:30:40 stef pcscd: ifdhandler.c:79:IFDHCreateChannelByName() lun: 0, device: usb:096e/0503:libudev:0:/dev/bus/usb/001/005 Sep 21 09:30:40 stef pcscd: ccid_usb.c:244:OpenUSBByName() ifdManufacturerString: Ludovic Rousseau (ludovic.rouss...@free.fr) Sep 21 09:30:40 stef pcscd: ccid_usb.c:245:OpenUSBByName() ifdProductString: Generic CCID driver Sep 21 09:30:40 stef pcscd: ccid_usb.c:246: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. Sep 21 09:30:40 stef pcscd: ccid_usb.c:485:OpenUSBByName() Found Vendor/Product: 096E/0503 (Feitian SCR301) Sep 21 09:30:40 stef pcscd: ccid_usb.c:487:OpenUSBByName() Using USB bus/device: 1/5 Sep 21 09:30:40 stef pcscd: ccid_usb.c:953:get_data_rates() declared: 10752 bps Sep 21 09:30:40 stef pcscd: ifdhandler.c:401:IFDHGetCapabilities() tag: 0xFB3, usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:30:40 stef pcscd: readerfactory.c:295:RFAddReader() Using the reader polling thread Sep 21 09:30:40 stef pcscd: ifdhandler.c:401:IFDHGetCapabilities() tag: 0xFAE, usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:30:40 stef pcscd: ifdhandler.c:489:IFDHGetCapabilities() Reader supports 1 slot(s) Sep 21 09:30:40 stef pcscd: hotplug_libudev.c:258:get_driver() Looking for a driver for VID: 0x0424, PID: 0x2504, path: /dev/bus/usb/001/004 Sep 21 09:30:40 stef pcscd: readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Feitian SCR301 00 00 Sep 21 09:30:40 stef pcscd: ifdhandler.c:1151:IFDHPowerICC() action: PowerUp, usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:30:40 stef pcscd: readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Feitian SCR301 00 00 Sep 21 09:30:40 stef pcscd: readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Feitian SCR301 00 00 Sep 21 09:30:40 stef pcscd: readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Feitian SCR301 00 00 Sep 21 09:30:40 stef pcscd: readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Feitian SCR301 00 00 Sep 21 09:30:40 stef pcscd: readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Feitian SCR301 00 00 Sep 21 09:30:40 stef pcscd: readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Feitian SCR301 00 00 Sep 21 09:30:40 stef pcscd: readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Feitian SCR301 00 00 Sep 21 09:30:40 stef pcscd: readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Feitian SCR301 00 00 Sep 21 09:30:40 stef pcscd: readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Feitian SCR301 00 00 Sep 21 09:30:40 stef pcscd: readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Feitian SCR301 00 00 Sep 21 09:30:40 stef pcscd: readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Feitian SCR301 00 00 Sep 21 09:30:40 stef pcscd: readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Feitian SCR301 00 00 Sep 21 09:30:40 stef pcscd: readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Feitian SCR301 00 00 Sep 21 09:30:40 stef pcscd: readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Feitian SCR301 00 00 Sep 21 09:30:40 stef pcscd: readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Feitian SCR301 00 00 Sep 21 09:30:40 stef pcscd: readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Feitian SCR301 00 00 Sep 21 09:30:40 stef pcscd: readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Feitian SCR301 00 00 Sep 21 09:30:40 stef pcscd: readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Feitian SCR301 00 00 Sep 21 09:30:40 stef pcscd: readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Feitian SCR301 00 00 Sep 21 09:30:40 stef pcscd: readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Feitian SCR301 00 00 Sep 21 09:30:40 stef pcscd: readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Feitian SCR301 00 00 Sep 21 09:30:40 stef pcscd: readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Feitian SCR301 00 00 Sep 21 09:30:40 stef pcscd: readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Feitian SCR301 00 00 Sep 21 09:30:40 stef pcscd: readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Feitian SCR301 00 00 Sep 21 09:30:40 stef pcscd: readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Feitian SCR301 00 00 Sep 21 09:30:40 stef pcscd: readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Feitian SCR301 00 00 Sep 21 09:30:40 stef pcscd: readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Feitian SCR301 00 00 Sep 21 09:30:40 stef pcscd: readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Feitian SCR301 00 00 Sep 21 09:30:40 stef pcscd: readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Feitian SCR301 00 00 Sep 21 09:30:40 stef pcscd: readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Feitian SCR301 00 00 Sep 21 09:30:40 stef pcscd: readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Feitian SCR301 00 00 Sep 21 09:30:40 stef pcscd: readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Feitian SCR301 00 00 Sep 21 09:30:40 stef pcscd: readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Feitian SCR301 00 00 Sep 21 09:30:40 stef pcscd: readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Feitian SCR301 00 00 Sep 21 09:30:40 stef pcscd: readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Feitian SCR301 00 00 Sep 21 09:30:40 stef pcscd: readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Feitian SCR301 00 00 Sep 21 09:30:40 stef pcscd: readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Feitian SCR301 00 00 Sep 21 09:30:40 stef pcscd: readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Feitian SCR301 00 00 Sep 21 09:30:40 stef pcscd: readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Feitian SCR301 00 00 Sep 21 09:30:40 stef pcscd: readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Feitian SCR301 00 00 Sep 21 09:30:40 stef pcscd: readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Feitian SCR301 00 00 Sep 21 09:30:40 stef pcscd: readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Feitian SCR301 00 00 Sep 21 09:30:40 stef pcscd: readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Feitian SCR301 00 00 Sep 21 09:30:40 stef pcscd: readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Feitian SCR301 00 00 Sep 21 09:30:40 stef pcscd: readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Feitian SCR301 00 00 Sep 21 09:30:40 stef pcscd: readerfactory.c:1301:RFWaitForReaderInit() Waiting init for reader: Feitian SCR301 00 00 Sep 21 09:30:40 stef pcscd: eventhandler.c:256:EHStatusHandlerThread() powerState: POWER_STATE_POWERED Sep 21 09:30:40 stef pcscd: Card ATR: 3B 9F 95 81 31 FE 9F 00 65 46 53 05 30 06 71 DF 00 00 00 81 61 0E D8 Sep 21 09:30:45 stef pcscd: ifdhandler.c:1151:IFDHPowerICC() action: PowerDown, usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:30:45 stef pcscd: eventhandler.c:446:EHStatusHandlerThread() powerState: POWER_STATE_UNPOWERED ***** Start of pkcs11-tool --module ./src/pkcs11/.libs/opensc-pkcs11.so --list-token-slots ***** Sep 21 09:30:58 stef pcscd: winscard_msg_srv.c:202:ProcessEventsServer() Common channel packet arrival Sep 21 09:30:58 stef pcscd: winscard_msg_srv.c:214:ProcessEventsServer() ProcessCommonChannelRequest detects: 5 Sep 21 09:30:58 stef pcscd: pcscdaemon.c:91:SVCServiceRunLoop() A new context thread creation is requested: 5 Sep 21 09:30:58 stef pcscd: winscard_svc.c:297:ContextThread() Thread is started: dwClientID=5, threadContext @1040130 Sep 21 09:30:58 stef pcscd: winscard_svc.c:315:ContextThread() Received command: CMD_VERSION from client 5 Sep 21 09:30:58 stef pcscd: winscard_svc.c:327:ContextThread() Client is protocol version 4:2 Sep 21 09:30:58 stef pcscd: winscard_svc.c:347:ContextThread() CMD_VERSION rv=0x0 for client 5 Sep 21 09:30:58 stef pcscd: winscard_svc.c:315:ContextThread() Received command: ESTABLISH_CONTEXT from client 5 Sep 21 09:30:58 stef pcscd: winscard.c:193:SCardEstablishContext() Establishing Context: 0x10365F9 Sep 21 09:30:58 stef pcscd: winscard_svc.c:406:ContextThread() ESTABLISH_CONTEXT rv=0x0 for client 5 Sep 21 09:30:58 stef pcscd: winscard_svc.c:315:ContextThread() Received command: CMD_GET_READERS_STATE from client 5 Sep 21 09:30:58 stef pcscd: winscard_svc.c:315:ContextThread() Received command: CMD_GET_READERS_STATE from client 5 Sep 21 09:30:58 stef pcscd: winscard_svc.c:315:ContextThread() Received command: CMD_GET_READERS_STATE from client 5 Sep 21 09:30:58 stef pcscd: winscard_svc.c:315:ContextThread() Received command: CONNECT from client 5 Sep 21 09:30:58 stef pcscd: winscard.c:235:SCardConnect() Attempting Connect to Feitian SCR301 00 00 using protocol: 3 Sep 21 09:30:58 stef pcscd: ifdhandler.c:1151:IFDHPowerICC() action: PowerUp, usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:30:59 stef pcscd: winscard.c:309:SCardConnect() power up complete. Sep 21 09:30:59 stef pcscd: Card ATR: 3B 9F 95 81 31 FE 9F 00 65 46 53 05 30 06 71 DF 00 00 00 81 61 0E D8 Sep 21 09:30:59 stef pcscd: winscard.c:328:SCardConnect() powerState: POWER_STATE_INUSE Sep 21 09:30:59 stef pcscd: prothandler.c:127:PHSetProtocol() Attempting PTS to T=1 Sep 21 09:30:59 stef pcscd: ifdhandler.c:700:IFDHSetProtocolParameters() protocol T=1, usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:30:59 stef pcscd: winscard.c:406:SCardConnect() Active Protocol: T=1 Sep 21 09:30:59 stef pcscd: winscard.c:426:SCardConnect() hCard Identity: 1adeb Sep 21 09:30:59 stef pcscd: winscard_svc.c:447:ContextThread() CONNECT rv=0x0 for client 5 Sep 21 09:30:59 stef pcscd: winscard_svc.c:315:ContextThread() Received command: CONTROL from client 5 Sep 21 09:30:59 stef pcscd: ifdhandler.c:1323:IFDHControl() ControlCode: 0x42000D48, usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:30:59 stef pcscd: Control TxBuffer: Sep 21 09:30:59 stef pcscd: Control RxBuffer: 0A 04 42 33 00 0A 12 04 42 33 00 12 Sep 21 09:30:59 stef pcscd: winscard_svc.c:646:ContextThread() CONTROL rv=0x0 for client 5 Sep 21 09:30:59 stef pcscd: winscard_svc.c:315:ContextThread() Received command: CONTROL from client 5 Sep 21 09:30:59 stef pcscd: ifdhandler.c:1323:IFDHControl() ControlCode: 0x4233000A, usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:30:59 stef pcscd: Control TxBuffer: Sep 21 09:30:59 stef pcscd: Control RxBuffer: 00 00 07 00 Sep 21 09:30:59 stef pcscd: winscard_svc.c:646:ContextThread() CONTROL rv=0x0 for client 5 Sep 21 09:30:59 stef pcscd: winscard_svc.c:315:ContextThread() Received command: DISCONNECT from client 5 Sep 21 09:30:59 stef pcscd: winscard.c:826:SCardDisconnect() Active Contexts: 1 Sep 21 09:30:59 stef pcscd: winscard.c:827:SCardDisconnect() dwDisposition: 0 Sep 21 09:30:59 stef pcscd: winscard.c:992:SCardDisconnect() powerState: POWER_STATE_GRACE_PERIOD Sep 21 09:30:59 stef pcscd: ifdhandler.c:401:IFDHGetCapabilities() tag: 0xFB2, usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:30:59 stef pcscd: winscard.c:1006:SCardDisconnect() Stoping polling thread Sep 21 09:30:59 stef pcscd: ifdhandler.c:366:IFDHStopPolling() usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:30:59 stef pcscd: winscard_svc.c:484:ContextThread() DISCONNECT rv=0x0 for client 5 Sep 21 09:30:59 stef pcscd: winscard_svc.c:315:ContextThread() Received command: CMD_GET_READERS_STATE from client 5 Sep 21 09:30:59 stef pcscd: winscard_svc.c:315:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 5 Sep 21 09:30:59 stef pcscd: winscard_svc.c:315:ContextThread() Received command: CMD_STOP_WAITING_READER_STATE_CHANGE from client 5 Sep 21 09:30:59 stef pcscd: winscard_svc.c:387:ContextThread() CMD_STOP_WAITING_READER_STATE_CHANGE rv=0x0 for client 5 Sep 21 09:30:59 stef pcscd: winscard_svc.c:315:ContextThread() Received command: CMD_GET_READERS_STATE from client 5 Sep 21 09:30:59 stef pcscd: winscard_svc.c:315:ContextThread() Received command: CMD_GET_READERS_STATE from client 5 Sep 21 09:30:59 stef pcscd: winscard_svc.c:315:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 5 Sep 21 09:30:59 stef pcscd: winscard_svc.c:315:ContextThread() Received command: CMD_STOP_WAITING_READER_STATE_CHANGE from client 5 Sep 21 09:30:59 stef pcscd: winscard_svc.c:387:ContextThread() CMD_STOP_WAITING_READER_STATE_CHANGE rv=0x0 for client 5 Sep 21 09:30:59 stef pcscd: winscard_svc.c:315:ContextThread() Received command: CMD_GET_READERS_STATE from client 5 Sep 21 09:30:59 stef pcscd: winscard_svc.c:315:ContextThread() Received command: CMD_GET_READERS_STATE from client 5 Sep 21 09:30:59 stef pcscd: winscard_svc.c:315:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 5 Sep 21 09:30:59 stef pcscd: winscard_svc.c:315:ContextThread() Received command: CMD_STOP_WAITING_READER_STATE_CHANGE from client 5 Sep 21 09:30:59 stef pcscd: winscard_svc.c:387:ContextThread() CMD_STOP_WAITING_READER_STATE_CHANGE rv=0x0 for client 5 Sep 21 09:30:59 stef pcscd: winscard_svc.c:315:ContextThread() Received command: CMD_GET_READERS_STATE from client 5 Sep 21 09:30:59 stef pcscd: winscard_svc.c:315:ContextThread() Received command: CONNECT from client 5 Sep 21 09:30:59 stef pcscd: winscard.c:235:SCardConnect() Attempting Connect to Feitian SCR301 00 00 using protocol: 3 Sep 21 09:30:59 stef pcscd: winscard.c:328:SCardConnect() powerState: POWER_STATE_INUSE Sep 21 09:30:59 stef pcscd: winscard.c:406:SCardConnect() Active Protocol: T=1 Sep 21 09:30:59 stef pcscd: winscard.c:426:SCardConnect() hCard Identity: 1523f Sep 21 09:30:59 stef pcscd: winscard_svc.c:447:ContextThread() CONNECT rv=0x0 for client 5 Sep 21 09:30:59 stef pcscd: winscard_svc.c:315:ContextThread() Received command: BEGIN_TRANSACTION from client 5 Sep 21 09:30:59 stef pcscd: winscard.c:1057:SCardBeginTransaction() Status: 0x00000000 Sep 21 09:30:59 stef pcscd: winscard_svc.c:499:ContextThread() BEGIN_TRANSACTION rv=0x0 for client 5 Sep 21 09:30:59 stef pcscd: winscard_svc.c:315:ContextThread() Received command: TRANSMIT from client 5 Sep 21 09:30:59 stef pcscd: winscard.c:1551:SCardTransmit() Send Protocol: T=1 Sep 21 09:30:59 stef pcscd: ifdhandler.c:1280:IFDHTransmitToICC() usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:30:59 stef pcscd: winscard_svc.c:602:ContextThread() TRANSMIT rv=0x0 for client 5 Sep 21 09:30:59 stef pcscd: winscard_svc.c:315:ContextThread() Received command: TRANSMIT from client 5 Sep 21 09:30:59 stef pcscd: winscard.c:1551:SCardTransmit() Send Protocol: T=1 Sep 21 09:30:59 stef pcscd: ifdhandler.c:1280:IFDHTransmitToICC() usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:30:59 stef pcscd: winscard_svc.c:602:ContextThread() TRANSMIT rv=0x0 for client 5 Sep 21 09:30:59 stef pcscd: winscard_svc.c:315:ContextThread() Received command: TRANSMIT from client 5 Sep 21 09:30:59 stef pcscd: winscard.c:1551:SCardTransmit() Send Protocol: T=1 Sep 21 09:30:59 stef pcscd: ifdhandler.c:1280:IFDHTransmitToICC() usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:30:59 stef pcscd: winscard_svc.c:602:ContextThread() TRANSMIT rv=0x0 for client 5 Sep 21 09:30:59 stef pcscd: winscard_svc.c:315:ContextThread() Received command: TRANSMIT from client 5 Sep 21 09:30:59 stef pcscd: winscard.c:1551:SCardTransmit() Send Protocol: T=1 Sep 21 09:30:59 stef pcscd: ifdhandler.c:1280:IFDHTransmitToICC() usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:30:59 stef pcscd: winscard_svc.c:602:ContextThread() TRANSMIT rv=0x0 for client 5 Sep 21 09:30:59 stef pcscd: winscard_svc.c:315:ContextThread() Received command: TRANSMIT from client 5 Sep 21 09:30:59 stef pcscd: winscard.c:1551:SCardTransmit() Send Protocol: T=1 Sep 21 09:30:59 stef pcscd: ifdhandler.c:1280:IFDHTransmitToICC() usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:30:59 stef pcscd: winscard_svc.c:602:ContextThread() TRANSMIT rv=0x0 for client 5 Sep 21 09:30:59 stef pcscd: winscard_svc.c:315:ContextThread() Received command: TRANSMIT from client 5 Sep 21 09:30:59 stef pcscd: winscard.c:1551:SCardTransmit() Send Protocol: T=1 Sep 21 09:30:59 stef pcscd: ifdhandler.c:1280:IFDHTransmitToICC() usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:30:59 stef pcscd: winscard_svc.c:602:ContextThread() TRANSMIT rv=0x0 for client 5 Sep 21 09:30:59 stef pcscd: winscard_svc.c:315:ContextThread() Received command: TRANSMIT from client 5 Sep 21 09:30:59 stef pcscd: winscard.c:1551:SCardTransmit() Send Protocol: T=1 Sep 21 09:30:59 stef pcscd: ifdhandler.c:1280:IFDHTransmitToICC() usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:30:59 stef pcscd: winscard_svc.c:602:ContextThread() TRANSMIT rv=0x0 for client 5 Sep 21 09:30:59 stef pcscd: winscard_svc.c:315:ContextThread() Received command: TRANSMIT from client 5 Sep 21 09:30:59 stef pcscd: winscard.c:1551:SCardTransmit() Send Protocol: T=1 Sep 21 09:30:59 stef pcscd: ifdhandler.c:1280:IFDHTransmitToICC() usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:31:00 stef pcscd: winscard_svc.c:602:ContextThread() TRANSMIT rv=0x0 for client 5 Sep 21 09:31:00 stef pcscd: winscard_svc.c:315:ContextThread() Received command: TRANSMIT from client 5 Sep 21 09:31:00 stef pcscd: winscard.c:1551:SCardTransmit() Send Protocol: T=1 Sep 21 09:31:00 stef pcscd: ifdhandler.c:1280:IFDHTransmitToICC() usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:31:00 stef pcscd: winscard_svc.c:602:ContextThread() TRANSMIT rv=0x0 for client 5 Sep 21 09:31:00 stef pcscd: winscard_svc.c:315:ContextThread() Received command: TRANSMIT from client 5 Sep 21 09:31:00 stef pcscd: winscard.c:1551:SCardTransmit() Send Protocol: T=1 Sep 21 09:31:00 stef pcscd: ifdhandler.c:1280:IFDHTransmitToICC() usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:31:00 stef pcscd: winscard_svc.c:602:ContextThread() TRANSMIT rv=0x0 for client 5 Sep 21 09:31:00 stef pcscd: winscard_svc.c:315:ContextThread() Received command: TRANSMIT from client 5 Sep 21 09:31:00 stef pcscd: winscard.c:1551:SCardTransmit() Send Protocol: T=1 Sep 21 09:31:00 stef pcscd: ifdhandler.c:1280:IFDHTransmitToICC() usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:31:00 stef pcscd: winscard_svc.c:602:ContextThread() TRANSMIT rv=0x0 for client 5 Sep 21 09:31:00 stef pcscd: winscard_svc.c:315:ContextThread() Received command: END_TRANSACTION from client 5 Sep 21 09:31:00 stef pcscd: winscard.c:1194:SCardEndTransaction() Status: 0x00000000 Sep 21 09:31:00 stef pcscd: winscard_svc.c:515:ContextThread() END_TRANSACTION rv=0x0 for client 5 Sep 21 09:31:00 stef pcscd: winscard_svc.c:315:ContextThread() Received command: BEGIN_TRANSACTION from client 5 Sep 21 09:31:00 stef pcscd: winscard.c:1057:SCardBeginTransaction() Status: 0x00000000 Sep 21 09:31:00 stef pcscd: winscard_svc.c:499:ContextThread() BEGIN_TRANSACTION rv=0x0 for client 5 Sep 21 09:31:00 stef pcscd: winscard_svc.c:315:ContextThread() Received command: TRANSMIT from client 5 Sep 21 09:31:00 stef pcscd: winscard.c:1551:SCardTransmit() Send Protocol: T=1 Sep 21 09:31:00 stef pcscd: ifdhandler.c:1280:IFDHTransmitToICC() usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:31:00 stef pcscd: winscard_svc.c:602:ContextThread() TRANSMIT rv=0x0 for client 5 Sep 21 09:31:00 stef pcscd: winscard_svc.c:315:ContextThread() Received command: TRANSMIT from client 5 Sep 21 09:31:00 stef pcscd: winscard.c:1551:SCardTransmit() Send Protocol: T=1 Sep 21 09:31:00 stef pcscd: ifdhandler.c:1280:IFDHTransmitToICC() usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) ***** 60 second wait ***** Sep 21 09:32:00 stef pcscd: winscard_svc.c:602:ContextThread() TRANSMIT rv=0x0 for client 5 Sep 21 09:32:00 stef pcscd: winscard_svc.c:315:ContextThread() Received command: TRANSMIT from client 5 Sep 21 09:32:00 stef pcscd: winscard.c:1551:SCardTransmit() Send Protocol: T=1 Sep 21 09:32:00 stef pcscd: ifdhandler.c:1280:IFDHTransmitToICC() usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:32:00 stef pcscd: winscard_svc.c:602:ContextThread() TRANSMIT rv=0x0 for client 5 Sep 21 09:32:00 stef pcscd: winscard_svc.c:315:ContextThread() Received command: END_TRANSACTION from client 5 Sep 21 09:32:00 stef pcscd: winscard.c:1194:SCardEndTransaction() Status: 0x00000000 Sep 21 09:32:00 stef pcscd: winscard_svc.c:515:ContextThread() END_TRANSACTION rv=0x0 for client 5 Sep 21 09:32:00 stef pcscd: winscard_svc.c:315:ContextThread() Received command: BEGIN_TRANSACTION from client 5 Sep 21 09:32:00 stef pcscd: winscard.c:1057:SCardBeginTransaction() Status: 0x00000000 Sep 21 09:32:00 stef pcscd: winscard_svc.c:499:ContextThread() BEGIN_TRANSACTION rv=0x0 for client 5 Sep 21 09:32:00 stef pcscd: winscard_svc.c:315:ContextThread() Received command: TRANSMIT from client 5 Sep 21 09:32:00 stef pcscd: winscard.c:1551:SCardTransmit() Send Protocol: T=1 Sep 21 09:32:00 stef pcscd: ifdhandler.c:1280:IFDHTransmitToICC() usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:32:00 stef pcscd: winscard_svc.c:602:ContextThread() TRANSMIT rv=0x0 for client 5 Sep 21 09:32:00 stef pcscd: winscard_svc.c:315:ContextThread() Received command: TRANSMIT from client 5 Sep 21 09:32:00 stef pcscd: winscard.c:1551:SCardTransmit() Send Protocol: T=1 Sep 21 09:32:00 stef pcscd: ifdhandler.c:1280:IFDHTransmitToICC() usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:32:01 stef pcscd: winscard_svc.c:602:ContextThread() TRANSMIT rv=0x0 for client 5 Sep 21 09:32:01 stef pcscd: winscard_svc.c:315:ContextThread() Received command: TRANSMIT from client 5 Sep 21 09:32:01 stef pcscd: winscard.c:1551:SCardTransmit() Send Protocol: T=1 Sep 21 09:32:01 stef pcscd: ifdhandler.c:1280:IFDHTransmitToICC() usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:32:01 stef pcscd: winscard_svc.c:602:ContextThread() TRANSMIT rv=0x0 for client 5 Sep 21 09:32:01 stef pcscd: winscard_svc.c:315:ContextThread() Received command: TRANSMIT from client 5 Sep 21 09:32:01 stef pcscd: winscard.c:1551:SCardTransmit() Send Protocol: T=1 Sep 21 09:32:01 stef pcscd: ifdhandler.c:1280:IFDHTransmitToICC() usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:32:01 stef pcscd: winscard_svc.c:602:ContextThread() TRANSMIT rv=0x0 for client 5 Sep 21 09:32:01 stef pcscd: winscard_svc.c:315:ContextThread() Received command: TRANSMIT from client 5 Sep 21 09:32:01 stef pcscd: winscard.c:1551:SCardTransmit() Send Protocol: T=1 Sep 21 09:32:01 stef pcscd: ifdhandler.c:1280:IFDHTransmitToICC() usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:32:01 stef pcscd: winscard_svc.c:602:ContextThread() TRANSMIT rv=0x0 for client 5 Sep 21 09:32:01 stef pcscd: winscard_svc.c:315:ContextThread() Received command: TRANSMIT from client 5 Sep 21 09:32:01 stef pcscd: winscard.c:1551:SCardTransmit() Send Protocol: T=1 Sep 21 09:32:01 stef pcscd: ifdhandler.c:1280:IFDHTransmitToICC() usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:32:02 stef pcscd: winscard_svc.c:602:ContextThread() TRANSMIT rv=0x0 for client 5 Sep 21 09:32:02 stef pcscd: winscard_svc.c:315:ContextThread() Received command: END_TRANSACTION from client 5 Sep 21 09:32:02 stef pcscd: winscard.c:1194:SCardEndTransaction() Status: 0x00000000 Sep 21 09:32:02 stef pcscd: winscard_svc.c:515:ContextThread() END_TRANSACTION rv=0x0 for client 5 Sep 21 09:32:02 stef pcscd: winscard_svc.c:315:ContextThread() Received command: BEGIN_TRANSACTION from client 5 Sep 21 09:32:02 stef pcscd: winscard.c:1057:SCardBeginTransaction() Status: 0x00000000 Sep 21 09:32:02 stef pcscd: winscard_svc.c:499:ContextThread() BEGIN_TRANSACTION rv=0x0 for client 5 Sep 21 09:32:02 stef pcscd: winscard_svc.c:315:ContextThread() Received command: TRANSMIT from client 5 Sep 21 09:32:02 stef pcscd: winscard.c:1551:SCardTransmit() Send Protocol: T=1 Sep 21 09:32:02 stef pcscd: ifdhandler.c:1280:IFDHTransmitToICC() usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:32:02 stef pcscd: winscard_svc.c:602:ContextThread() TRANSMIT rv=0x0 for client 5 Sep 21 09:32:02 stef pcscd: winscard_svc.c:315:ContextThread() Received command: TRANSMIT from client 5 Sep 21 09:32:02 stef pcscd: winscard.c:1551:SCardTransmit() Send Protocol: T=1 Sep 21 09:32:02 stef pcscd: ifdhandler.c:1280:IFDHTransmitToICC() usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:32:02 stef pcscd: winscard_svc.c:602:ContextThread() TRANSMIT rv=0x0 for client 5 Sep 21 09:32:02 stef pcscd: winscard_svc.c:315:ContextThread() Received command: TRANSMIT from client 5 Sep 21 09:32:02 stef pcscd: winscard.c:1551:SCardTransmit() Send Protocol: T=1 Sep 21 09:32:02 stef pcscd: ifdhandler.c:1280:IFDHTransmitToICC() usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:32:02 stef pcscd: winscard_svc.c:602:ContextThread() TRANSMIT rv=0x0 for client 5 Sep 21 09:32:02 stef pcscd: winscard_svc.c:315:ContextThread() Received command: TRANSMIT from client 5 Sep 21 09:32:02 stef pcscd: winscard.c:1551:SCardTransmit() Send Protocol: T=1 Sep 21 09:32:02 stef pcscd: ifdhandler.c:1280:IFDHTransmitToICC() usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:32:03 stef pcscd: winscard_svc.c:602:ContextThread() TRANSMIT rv=0x0 for client 5 Sep 21 09:32:03 stef pcscd: winscard_svc.c:315:ContextThread() Received command: TRANSMIT from client 5 Sep 21 09:32:03 stef pcscd: winscard.c:1551:SCardTransmit() Send Protocol: T=1 Sep 21 09:32:03 stef pcscd: ifdhandler.c:1280:IFDHTransmitToICC() usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:32:03 stef pcscd: winscard_svc.c:602:ContextThread() TRANSMIT rv=0x0 for client 5 Sep 21 09:32:03 stef pcscd: winscard_svc.c:315:ContextThread() Received command: TRANSMIT from client 5 Sep 21 09:32:03 stef pcscd: winscard.c:1551:SCardTransmit() Send Protocol: T=1 Sep 21 09:32:03 stef pcscd: ifdhandler.c:1280:IFDHTransmitToICC() usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:32:03 stef pcscd: winscard_svc.c:602:ContextThread() TRANSMIT rv=0x0 for client 5 Sep 21 09:32:03 stef pcscd: winscard_svc.c:315:ContextThread() Received command: TRANSMIT from client 5 Sep 21 09:32:03 stef pcscd: winscard.c:1551:SCardTransmit() Send Protocol: T=1 Sep 21 09:32:03 stef pcscd: ifdhandler.c:1280:IFDHTransmitToICC() usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:32:03 stef pcscd: winscard_svc.c:602:ContextThread() TRANSMIT rv=0x0 for client 5 Sep 21 09:32:03 stef pcscd: winscard_svc.c:315:ContextThread() Received command: TRANSMIT from client 5 Sep 21 09:32:03 stef pcscd: winscard.c:1551:SCardTransmit() Send Protocol: T=1 Sep 21 09:32:03 stef pcscd: ifdhandler.c:1280:IFDHTransmitToICC() usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:32:04 stef pcscd: winscard_svc.c:602:ContextThread() TRANSMIT rv=0x0 for client 5 Sep 21 09:32:04 stef pcscd: winscard_svc.c:315:ContextThread() Received command: TRANSMIT from client 5 Sep 21 09:32:04 stef pcscd: winscard.c:1551:SCardTransmit() Send Protocol: T=1 Sep 21 09:32:04 stef pcscd: ifdhandler.c:1280:IFDHTransmitToICC() usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:32:04 stef pcscd: winscard_svc.c:602:ContextThread() TRANSMIT rv=0x0 for client 5 Sep 21 09:32:04 stef pcscd: winscard_svc.c:315:ContextThread() Received command: TRANSMIT from client 5 Sep 21 09:32:04 stef pcscd: winscard.c:1551:SCardTransmit() Send Protocol: T=1 Sep 21 09:32:04 stef pcscd: ifdhandler.c:1280:IFDHTransmitToICC() usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:32:04 stef pcscd: winscard_svc.c:602:ContextThread() TRANSMIT rv=0x0 for client 5 Sep 21 09:32:04 stef pcscd: winscard_svc.c:315:ContextThread() Received command: TRANSMIT from client 5 Sep 21 09:32:04 stef pcscd: winscard.c:1551:SCardTransmit() Send Protocol: T=1 Sep 21 09:32:04 stef pcscd: ifdhandler.c:1280:IFDHTransmitToICC() usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:32:04 stef pcscd: winscard_svc.c:602:ContextThread() TRANSMIT rv=0x0 for client 5 Sep 21 09:32:04 stef pcscd: winscard_svc.c:315:ContextThread() Received command: END_TRANSACTION from client 5 Sep 21 09:32:04 stef pcscd: winscard.c:1194:SCardEndTransaction() Status: 0x00000000 Sep 21 09:32:04 stef pcscd: winscard_svc.c:515:ContextThread() END_TRANSACTION rv=0x0 for client 5 Sep 21 09:32:04 stef pcscd: winscard_svc.c:315:ContextThread() Received command: BEGIN_TRANSACTION from client 5 Sep 21 09:32:04 stef pcscd: winscard.c:1057:SCardBeginTransaction() Status: 0x00000000 Sep 21 09:32:04 stef pcscd: winscard_svc.c:499:ContextThread() BEGIN_TRANSACTION rv=0x0 for client 5 Sep 21 09:32:04 stef pcscd: winscard_svc.c:315:ContextThread() Received command: TRANSMIT from client 5 Sep 21 09:32:04 stef pcscd: winscard.c:1551:SCardTransmit() Send Protocol: T=1 Sep 21 09:32:04 stef pcscd: ifdhandler.c:1280:IFDHTransmitToICC() usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:32:04 stef pcscd: winscard_svc.c:602:ContextThread() TRANSMIT rv=0x0 for client 5 Sep 21 09:32:04 stef pcscd: winscard_svc.c:315:ContextThread() Received command: TRANSMIT from client 5 Sep 21 09:32:04 stef pcscd: winscard.c:1551:SCardTransmit() Send Protocol: T=1 Sep 21 09:32:04 stef pcscd: ifdhandler.c:1280:IFDHTransmitToICC() usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:32:05 stef pcscd: winscard_svc.c:602:ContextThread() TRANSMIT rv=0x0 for client 5 Sep 21 09:32:05 stef pcscd: winscard_svc.c:315:ContextThread() Received command: TRANSMIT from client 5 Sep 21 09:32:05 stef pcscd: winscard.c:1551:SCardTransmit() Send Protocol: T=1 Sep 21 09:32:05 stef pcscd: ifdhandler.c:1280:IFDHTransmitToICC() usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:32:05 stef pcscd: winscard_svc.c:602:ContextThread() TRANSMIT rv=0x0 for client 5 Sep 21 09:32:05 stef pcscd: winscard_svc.c:315:ContextThread() Received command: TRANSMIT from client 5 Sep 21 09:32:05 stef pcscd: winscard.c:1551:SCardTransmit() Send Protocol: T=1 Sep 21 09:32:05 stef pcscd: ifdhandler.c:1280:IFDHTransmitToICC() usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:32:05 stef pcscd: winscard_svc.c:602:ContextThread() TRANSMIT rv=0x0 for client 5 Sep 21 09:32:05 stef pcscd: winscard_svc.c:315:ContextThread() Received command: TRANSMIT from client 5 Sep 21 09:32:05 stef pcscd: winscard.c:1551:SCardTransmit() Send Protocol: T=1 Sep 21 09:32:05 stef pcscd: ifdhandler.c:1280:IFDHTransmitToICC() usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:32:05 stef pcscd: winscard_svc.c:602:ContextThread() TRANSMIT rv=0x0 for client 5 Sep 21 09:32:05 stef pcscd: winscard_svc.c:315:ContextThread() Received command: TRANSMIT from client 5 Sep 21 09:32:05 stef pcscd: winscard.c:1551:SCardTransmit() Send Protocol: T=1 Sep 21 09:32:05 stef pcscd: ifdhandler.c:1280:IFDHTransmitToICC() usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:32:06 stef pcscd: winscard_svc.c:602:ContextThread() TRANSMIT rv=0x0 for client 5 Sep 21 09:32:06 stef pcscd: winscard_svc.c:315:ContextThread() Received command: TRANSMIT from client 5 Sep 21 09:32:06 stef pcscd: winscard.c:1551:SCardTransmit() Send Protocol: T=1 Sep 21 09:32:06 stef pcscd: ifdhandler.c:1280:IFDHTransmitToICC() usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:32:06 stef pcscd: winscard_svc.c:602:ContextThread() TRANSMIT rv=0x0 for client 5 Sep 21 09:32:06 stef pcscd: winscard_svc.c:315:ContextThread() Received command: END_TRANSACTION from client 5 Sep 21 09:32:06 stef pcscd: winscard.c:1194:SCardEndTransaction() Status: 0x00000000 Sep 21 09:32:06 stef pcscd: winscard_svc.c:515:ContextThread() END_TRANSACTION rv=0x0 for client 5 Sep 21 09:32:06 stef pcscd: winscard_svc.c:315:ContextThread() Received command: CMD_GET_READERS_STATE from client 5 Sep 21 09:32:06 stef pcscd: winscard_svc.c:315:ContextThread() Received command: CMD_GET_READERS_STATE from client 5 Sep 21 09:32:06 stef pcscd: winscard_svc.c:315:ContextThread() Received command: CMD_GET_READERS_STATE from client 5 Sep 21 09:32:06 stef pcscd: winscard_svc.c:315:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 5 Sep 21 09:32:06 stef pcscd: winscard_svc.c:315:ContextThread() Received command: CMD_STOP_WAITING_READER_STATE_CHANGE from client 5 Sep 21 09:32:06 stef pcscd: winscard_svc.c:387:ContextThread() CMD_STOP_WAITING_READER_STATE_CHANGE rv=0x0 for client 5 Sep 21 09:32:06 stef pcscd: winscard_svc.c:315:ContextThread() Received command: CMD_GET_READERS_STATE from client 5 Sep 21 09:32:06 stef pcscd: winscard_svc.c:315:ContextThread() Received command: CMD_GET_READERS_STATE from client 5 Sep 21 09:32:06 stef pcscd: winscard_svc.c:315:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 5 Sep 21 09:32:06 stef pcscd: winscard_svc.c:315:ContextThread() Received command: CMD_STOP_WAITING_READER_STATE_CHANGE from client 5 Sep 21 09:32:06 stef pcscd: winscard_svc.c:387:ContextThread() CMD_STOP_WAITING_READER_STATE_CHANGE rv=0x0 for client 5 Sep 21 09:32:06 stef pcscd: winscard_svc.c:315:ContextThread() Received command: CMD_GET_READERS_STATE from client 5 Sep 21 09:32:06 stef pcscd: winscard_svc.c:315:ContextThread() Received command: CMD_GET_READERS_STATE from client 5 Sep 21 09:32:06 stef pcscd: winscard_svc.c:315:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 5 Sep 21 09:32:06 stef pcscd: winscard_svc.c:315:ContextThread() Received command: CMD_STOP_WAITING_READER_STATE_CHANGE from client 5 Sep 21 09:32:06 stef pcscd: winscard_svc.c:387:ContextThread() CMD_STOP_WAITING_READER_STATE_CHANGE rv=0x0 for client 5 Sep 21 09:32:06 stef pcscd: winscard_svc.c:315:ContextThread() Received command: CMD_GET_READERS_STATE from client 5 Sep 21 09:32:06 stef pcscd: winscard_svc.c:315:ContextThread() Received command: DISCONNECT from client 5 Sep 21 09:32:06 stef pcscd: winscard.c:826:SCardDisconnect() Active Contexts: 1 Sep 21 09:32:06 stef pcscd: winscard.c:827:SCardDisconnect() dwDisposition: 1 Sep 21 09:32:06 stef pcscd: ifdhandler.c:1151:IFDHPowerICC() action: Reset, usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:32:06 stef pcscd: winscard.c:893:SCardDisconnect() Reset complete. Sep 21 09:32:06 stef pcscd: Card ATR: 3B 9F 95 81 31 FE 9F 00 65 46 53 05 30 06 71 DF 00 00 00 81 61 0E D8 Sep 21 09:32:06 stef pcscd: winscard.c:992:SCardDisconnect() powerState: POWER_STATE_GRACE_PERIOD Sep 21 09:32:06 stef pcscd: ifdhandler.c:401:IFDHGetCapabilities() tag: 0xFB2, usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:32:06 stef pcscd: winscard.c:1006:SCardDisconnect() Stoping polling thread Sep 21 09:32:06 stef pcscd: ifdhandler.c:366:IFDHStopPolling() usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:32:06 stef pcscd: winscard_svc.c:484:ContextThread() DISCONNECT rv=0x0 for client 5 Sep 21 09:32:06 stef pcscd: winscard_svc.c:315:ContextThread() Received command: RELEASE_CONTEXT from client 5 Sep 21 09:32:06 stef pcscd: winscard.c:204:SCardReleaseContext() Releasing Context: 0x10365F9 Sep 21 09:32:06 stef pcscd: winscard_svc.c:421:ContextThread() RELEASE_CONTEXT rv=0x0 for client 5 Sep 21 09:32:06 stef pcscd: winscard_svc.c:307:ContextThread() Client die: 5 Sep 21 09:32:06 stef pcscd: winscard_svc.c:916:MSGCleanupClient() Thread is stopping: dwClientID=5, threadContext @1040130 Sep 21 09:32:06 stef pcscd: winscard_svc.c:922:MSGCleanupClient() Freeing SCONTEXT @1040130 Sep 21 09:32:06 stef pcscd: eventhandler.c:458:EHStatusHandlerThread() powerState: POWER_STATE_POWERED ***** End of pkcs11-tool --module ./src/pkcs11/.libs/opensc-pkcs11.so --list-token-slots ***** Sep 21 09:32:11 stef pcscd: ifdhandler.c:1151:IFDHPowerICC() action: PowerDown, usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:32:11 stef pcscd: eventhandler.c:446:EHStatusHandlerThread() powerState: POWER_STATE_UNPOWERED Sep 21 09:33:44 stef pcscd: pcscdaemon.c:676:signal_trap() Received signal: 15 Sep 21 09:33:44 stef pcscd: pcscdaemon.c:681:signal_trap() Preparing for suicide Sep 21 09:33:45 stef pcscd: readerfactory.c:1254:RFCleanupReaders() entering cleaning function Sep 21 09:33:45 stef pcscd: readerfactory.c:1263:RFCleanupReaders() Stopping reader: Feitian SCR301 00 00 Sep 21 09:33:45 stef pcscd: eventhandler.c:148:EHDestroyEventHandler() Stomping thread. Sep 21 09:33:45 stef pcscd: ifdhandler.c:401:IFDHGetCapabilities() tag: 0xFB1, usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:33:45 stef pcscd: ifdhandler.c:401:IFDHGetCapabilities() tag: 0xFB2, usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:33:45 stef pcscd: eventhandler.c:173:EHDestroyEventHandler() Request stoping of polling thread Sep 21 09:33:45 stef pcscd: ifdhandler.c:366:IFDHStopPolling() usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:33:46 stef pcscd: eventhandler.c:469:EHStatusHandlerThread() Die Sep 21 09:33:46 stef pcscd: eventhandler.c:188:EHDestroyEventHandler() Thread stomped. Sep 21 09:33:46 stef pcscd: readerfactory.c:985:RFUnInitializeReader() Attempting shutdown of Feitian SCR301 00 00. Sep 21 09:33:46 stef pcscd: ifdhandler.c:293:IFDHCloseChannel() usb:096e/0503:libudev:0:/dev/bus/usb/001/005 (lun: 0) Sep 21 09:33:46 stef pcscd: readerfactory.c:861:RFUnloadReader() Unloading reader driver. Sep 21 09:33:46 stef pcscd: winscard_svc.c:130:ContextsDeinitialize() remaining threads: 0 Sep 21 09:33:46 stef pcscd: pcscdaemon.c:628:at_exit() cleaning /var/run
_______________________________________________ opensc-devel mailing list opensc-devel@lists.opensc-project.org http://www.opensc-project.org/mailman/listinfo/opensc-devel
