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
0x003763ad91d3
21 0x003764206cd9
20 SCardTransmit() 0x0037642041bf
19 pcsc_internal_transmit()
/data/projects/opensc/src/libopensc/reader-pcsc.c:188 0x77cbb26e
18 pcsc_transmit()
/data/projects/opensc/src/libopensc/reader-pcsc.c:246 0x77cbb4f7
17 do_single_transmit() /data/projects/opensc/src/libopensc/apdu.c:394
0x77c9f667
16 sc_transmit_apdu() /data/projects/opensc/src/libopensc/apdu.c:603
0x77c9fe2a
15 entersafe_transmit_apdu()
/data/projects/opensc/src/libopensc/card-entersafe.c:360 0x77cf447d
14 entersafe_read_binary()
/data/projects/opensc/src/libopensc/card-entersafe.c:390 0x77cf4670
13 sc_read_binary() /data/projects/opensc/src/libopensc/card.c:454
0x77c945ce
12 sc_read_binary() /data/projects/opensc/src/libopensc/card.c:437
0x77c943b6
11 sc_pkcs15_read_file()
/data/projects/opensc/src/libopensc/pkcs15.c:1930 0x77ca61fc
10 sc_pkcs15_parse_df()
/data/projects/opensc/src/libopensc/pkcs15.c:1636 0x77ca52db
9 __sc_pkcs15_search_objects()
/data/projects/opensc/src/libopensc/pkcs15.c:1023 0x77ca3cb2
8 sc_pkcs15_get_objects_cond()
/data/projects/opensc/src/libopensc/pkcs15.c:1247 0x77ca4461
7 sc_pkcs15_get_objects()
/data/projects/opensc/src/libopensc/pkcs15.c:1054 0x77ca3de2
6 pkcs15_create_pkcs11_objects()
/data/projects/opensc/src/pkcs11/framework-pkcs15.c:572 0x77a2fb9e
5 pkcs15_create_tokens()
/data/projects/opensc/src/pkcs11/framework-pkcs15.c:931 0x77a30af5
4 card_detect() /data/projects/opensc/src/pkcs11/slot.c:255
0x77a2c64f
3 initialize_reader() /data/projects/opensc/src/pkcs11/slot.c:132
0x77a2c0eb
2 C_Initialize() /data/projects/opensc/src/pkcs11/pkcs11-global.c:248
0x77a26f14
1 main() /data/projects/opensc/src/tools/pkcs11-tool.c:594
0x00402ffa
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/00