Nitrokey HSM 2 - Communication/detection issue with pkcs11-tool

garettet · May 14, 2025, 1:55pm

Hi,

I am having issue detecting Nitrokey HSM 2 using pkcs11-tool from OpenSC v0.26.1 on Windows 10. I am also seeing this issue using WSL.

Most of the time, using “pkcs11-tool” (-L, -T or --init-token) runs forever and never finds the Nitrokey HSM. Unplugging the device ends the command. Note that the USB device is correctly detected by the computer. It looks like pkcs11-tool has trouble communicating with the HSM and is stuck forever in a loop.

Some times, it is found correctly :

I encounter the same problem using SmartCardShell’s Key Manager and sc-hsm-tool.

This happens with different keys ordered recently. I had no trouble before with a key ordered in December 2024.

Does anyone have an idea what the problem could be ?
Thanks

FlorianSkamrahl · May 19, 2025, 8:13am

I have exactly the same problems on Windows 11 and have also tried the last 6 versions of OpenSC (0.26, 0.25, 0.24, 0.23 etc.) … always with the same problem

garettet · May 20, 2025, 8:16am

Hi,

Did you also have success with an older Nitrokey HSM ? If yes, this might be caused by newer HW/SW versions of the HSM …

I have also tried these HSMs on another computer running Ubuntu and encountered exactly the same behavior.

sc-hsm · May 20, 2025, 3:20pm

A good strategy to diagnose these kind of problems, is to run the pcscd on Linux in foreground mode.

First disable the pcscd service with

systemctl stop pcscd.socket
systemctl stop pcscd.service

Then run pcscd manually with

/usr/sbin/pcscd -a -f- d

Then you should see the interaction with the Nitrokey-HSM and what problem occur.

garettet · May 21, 2025, 9:57am

Thanks for your reply. Running pcscd manually solved the communication problem for 5 Nitrokey-HSM and I have been able to use them properly.

But only for one HSM, the problem remains and pcsd displays the following message :

00000000 [140454994420224] debuglog.c:299:DebugLogSetLevel() debug level=debug
00000224 [140454994420224] configfile.l:293:DBGetReaderListDir() Parsing conf directory: /etc/reader.conf.d
00000062 [140454994420224] configfile.l:329:DBGetReaderListDir() Skipping non regular file: .
00000006 [140454994420224] configfile.l:329:DBGetReaderListDir() Skipping non regular file: ..
00000003 [140454994420224] configfile.l:369:DBGetReaderList() Parsing conf file: /etc/reader.conf.d/libccidtwin
00000070 [140454994420224] pcscdaemon.c:663:main() pcsc-lite 1.9.5 daemon ready.
00002422 [140454994420224] hotplug_libudev.c:300:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/001/001
00000110 [140454994420224] hotplug_libudev.c:300:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/001/001
00000105 [140454994420224] hotplug_libudev.c:300:get_driver() Looking for a driver for VID: 0x20A0, PID: 0x4230, path: /dev/bus/usb/001/002
00000021 [140454994420224] hotplug_libudev.c:441:HPAddDevice() Adding USB device: Nitrokey Nitrokey HSM
00000035 [140454994420224] readerfactory.c:1097:RFInitializeReader() Attempting startup of Nitrokey Nitrokey HSM (01A001000000000         ) 00 00 using /usr/lib/pcsc/drivers/ifd-ccid.bundle/Contents/Linux/libccid.so
00000178 [140454994420224] readerfactory.c:972:RFBindFunctions() Loading IFD Handler 3.0
00000037 [140454994420224] ifdhandler.c:2071:init_driver() Driver version: 1.5.0
00000644 [140454994420224] ifdhandler.c:2088:init_driver() LogLevel: 0x0003
00000025 [140454994420224] ifdhandler.c:2099:init_driver() DriverOptions: 0x0000
00000216 [140454994420224] ifdhandler.c:110:CreateChannelByNameOrChannel() Lun: 0, device: usb:20a0/4230:libudev:0:/dev/bus/usb/001/002
00000032 [140454994420224] ccid_usb.c:317:OpenUSBByName() Using: /usr/lib/pcsc/drivers/ifd-ccid.bundle/Contents/Info.plist
00000662 [140454994420224] ccid_usb.c:335:OpenUSBByName() ifdManufacturerString: Ludovic Rousseau (ludovic.rousseau@free.fr)
00000020 [140454994420224] ccid_usb.c:336:OpenUSBByName() ifdProductString: Generic CCID driver
00000004 [140454994420224] ccid_usb.c:337: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.
00001420 [140454994420224] ccid_usb.c:679:OpenUSBByName() Found Vendor/Product: 20A0/4230 (Nitrokey Nitrokey HSM)
00000008 [140454994420224] ccid_usb.c:681:OpenUSBByName() Using USB bus/device: 1/2
00000003 [140454994420224] ccid_usb.c:744:OpenUSBByName() bNumDataRatesSupported is 0
03008886 [140454994420224] ccid_usb.c:993:ReadUSB() read failed (1/2): LIBUSB_ERROR_TIMEOUT
00101464 [140454994420224] ccid_usb.c:993:ReadUSB() read failed (1/2): LIBUSB_ERROR_TIMEOUT
00101665 [140454994420224] ccid_usb.c:993:ReadUSB() read failed (1/2): LIBUSB_ERROR_TIMEOUT
00000033 [140454994420224] ifdhandler.c:202:CreateChannelByNameOrChannel() failed
00000021 [140454994420224] ccid_usb.c:204:close_libusb_if_needed() libusb_exit
00000163 [140454994420224] readerfactory.c:1138:RFInitializeReader() Open Port 0x200000 Failed (usb:20a0/4230:libudev:0:/dev/bus/usb/001/002)
00000007 [140454994420224] readerfactory.c:380:RFAddReader() Nitrokey Nitrokey HSM (01A001000000000         ) init failed.
00000004 [140454994420224] readerfactory.c:632:RFRemoveReader() UnrefReader() count was: 1
00000002 [140454994420224] readerfactory.c:1151:RFUnInitializeReader() Attempting shutdown of Nitrokey Nitrokey HSM (01A001000000000         ) 00 00.
00000002 [140454994420224] readerfactory.c:1009:RFUnloadReader() Unloading reader driver.
00000052 [140454994420224] hotplug_libudev.c:538:HPAddDevice() Failed adding USB device: Nitrokey Nitrokey HSM
00000175 [140454994420224] hotplug_libudev.c:300:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0003, path: /dev/bus/usb/002/001

There seems to be a problem with USB communication.
lsusb -v displays the same informations with this HSM and the others correctly working.
Do you have any suggestions ?

notthetup · May 23, 2025, 4:44am

I’m seeing the exact same error with LIBUSB_ERROR_TIMEOUT. This is a brand new Nitrokey HSM 2 I just received.

@sc-hsm Any ideas what’s wrong?

sc-hsm · May 23, 2025, 8:34am

No idea what could be the exact cause, but I would suspect that this has to do with the Nitrokey HSM reader firmware.

The Nitrokey HSM is a CCID compatible Micro-SIM card reader with a SmartCard-HSM applet on the SIM card. There are a number of other integrations with SIM card readers or embedded SEs and we do not see that issue there. @Jan Anything changed recently ?

simon · May 23, 2025, 9:10am

We are investigating this issue currently since it appears on multiple Nitrokey HSM 2.

The issue seems to appear very often on Windows when the Nitrokey is plugged in during boot. A workaround is to have it only plugged in after boot. This is only a workaround which might not always work.

We are currently investigating options for a proper fix.

Best regards
Simon

notthetup · May 24, 2025, 10:57am

I am seeing this on Linux Ubuntu 22.04/ARM regardless if I plug it in at boot or after boot.

SkylerF · May 26, 2025, 11:40pm

I am having the same issue with my new Nitrokey HSM 2 on Arch Linux.

pcscd --version
pcsc-lite version 2.3.3
Copyright (C) 1999-2002 by David Corcoran <corcoran@musclecard.com>.
Copyright (C) 2001-2024 by Ludovic Rousseau <ludovic.rousseau@free.fr>.
Copyright (C) 2003-2004 by Damien Sauveron <sauveron@labri.fr>.
Report bugs to <pcsclite-muscle@lists.infradead.org>.
Enabled features: USB serial filter_names libudev polkit systemd Linux x86_64 ipcdir=/run/pcscd usbdropdir=/usr/lib/pcsc/drivers serialconfdir=/etc/reader.conf.d
MAX_READERNAME: 128, PCSCLITE_MAX_READERS_CONTEXTS: 16

pcscd -a -f -d                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                     19:26:09 [0/0]
00000000 ../PCSC/src/debuglog.c:395:DebugLogSetLevel() debug level=debug
00000122 ../PCSC/src/configfile.l:293:DBGetReaderListDir() Parsing conf directory: /etc/reader.conf.d
00000014 ../PCSC/src/configfile.l:326:DBGetReaderListDir() Skipping non regular file: .
00000003 ../PCSC/src/configfile.l:326:DBGetReaderListDir() Skipping non regular file: ..
00000002 ../PCSC/src/configfile.l:365:DBGetReaderList() Parsing conf file: /etc/reader.conf.d/libccidtwin
00000036 ../PCSC/src/pcscdaemon.c:669:main() pcsc-lite 2.3.3 daemon ready.
00000072 ../PCSC/src/pcscdaemon.c:752:main() Using drivers directory: /usr/lib/pcsc/drivers
00003371 ../PCSC/src/hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/002/001
00000243 ../PCSC/src/hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/002/001
00000210 ../PCSC/src/hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x0424, PID: 0x2660, path: /dev/bus/usb/002/002
00000185 ../PCSC/src/hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/002/001
00000142 ../PCSC/src/hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x051D, PID: 0x0002, path: /dev/bus/usb/002/004
00000129 ../PCSC/src/hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/002/001
00000150 ../PCSC/src/hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x17EF, PID: 0x608C, path: /dev/bus/usb/002/006
00000146 ../PCSC/src/hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x17EF, PID: 0x608C, path: /dev/bus/usb/002/006
00000269 ../PCSC/src/hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0003, path: /dev/bus/usb/003/001
00000334 ../PCSC/src/hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0001, path: /dev/bus/usb/001/001
24645027 ../PCSC/src/hotplug_libudev.c:656:HPEstablishUSBNotifications() USB Device add
00000122 ../PCSC/src/hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x20A0, PID: 0x4230, path: /dev/bus/usb/002/009
00000079 ../PCSC/src/hotplug_libudev.c:430:HPAddDevice() Adding USB device: Nitrokey Nitrokey HSM
00000070 ../PCSC/src/readerfactory.c:1103:RFInitializeReader() Attempting startup of Nitrokey Nitrokey HSM (XXXXXXXXXXXXXXX         ) 00 00 using /usr/lib/pcsc/drivers/ifd-ccid.bundle/Contents/Linux/libccid.so
00000245 ../PCSC/src/readerfactory.c:977:RFBindFunctions() Loading IFD Handler 3.0
00000017 ifdhandler.c:2088:init_driver() Driver version: 1.5.5
00000746 ifdhandler.c:2110:init_driver() LogLevel: 0x0003
00000006 ifdhandler.c:2121:init_driver() DriverOptions: 0x0000
00000240 ifdhandler.c:111:CreateChannelByNameOrChannel() Lun: 0, device: usb:20a0/4230:libudev:0:/dev/bus/usb/002/009
00000011 ccid_usb.c:331:OpenUSBByName() Using: /usr/lib/pcsc/drivers/ifd-ccid.bundle/Contents/Info.plist
00000667 ccid_usb.c:349:OpenUSBByName() ifdManufacturerString: Ludovic Rousseau (ludovic.rousseau@free.fr)
00000005 ccid_usb.c:350:OpenUSBByName() ifdProductString: Generic CCID driver
00000003 ccid_usb.c:351: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.
00004265 ccid_usb.c:747:OpenUSBByName() Found Vendor/Product: 20A0/4230 (Nitrokey Nitrokey HSM)
00000004 ccid_usb.c:749:OpenUSBByName() Using USB bus/device: 2/9
00000003 ccid_usb.c:814:OpenUSBByName() bNumDataRatesSupported is 0
00008661 ifdhandler.c:389:IFDHGetCapabilities() tag: 0xFB3, usb:20a0/4230:libudev:0:/dev/bus/usb/002/009 (lun: 0)
00000007 ../PCSC/src/readerfactory.c:391:RFAddReader() Using the reader polling thread
00000218 ifdhandler.c:389:IFDHGetCapabilities() tag: 0xFAE, usb:20a0/4230:libudev:0:/dev/bus/usb/002/009 (lun: 0)
00000007 ifdhandler.c:473:IFDHGetCapabilities() Reader supports 1 slot(s)
00000257 ifdhandler.c:1232:IFDHPowerICC() action: PowerUp, usb:20a0/4230:libudev:0:/dev/bus/usb/002/009 (lun: 0)
02200959 ../PCSC/src/eventhandler.c:287:EHStatusHandlerThread() powerState: POWER_STATE_POWERED
00000028 Card ATR: 3B DE 96 FF 81 91 FE 1F C3 80 31 81 54 48 53 4D 31 73 80 21 40 81 07 92
05000880 ifdhandler.c:1232:IFDHPowerICC() action: PowerDown, usb:20a0/4230:libudev:0:/dev/bus/usb/002/009 (lun: 0)
00000208 ../PCSC/src/eventhandler.c:480:EHStatusHandlerThread() powerState: POWER_STATE_UNPOWERED
99999999 ../PCSC/src/winscard_msg_srv.c:253:ProcessEventsServer() Common channel packet arrival
00000027 ../PCSC/src/winscard_msg_srv.c:264:ProcessEventsServer() ProcessCommonChannelRequest detects: 12
00000003 ../PCSC/src/pcscdaemon.c:130:SVCServiceRunLoop() A new context thread creation is requested: 12
00003396 ../PCSC/src/winscard_svc.c:362:ContextThread() Authorized PC/SC client
00000005 ../PCSC/src/winscard_svc.c:365:ContextThread() Thread is started: dwClientID=12, threadContext @0x56c9e98df8d0
00000007 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: CMD_VERSION from client 12
00000005 ../PCSC/src/winscard_svc.c:395:ContextThread() Client is protocol version 4:5
00000002 ../PCSC/src/winscard_svc.c:418:ContextThread() CMD_VERSION for client 12, rv=SCARD_S_SUCCESS
00000027 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: ESTABLISH_CONTEXT from client 12
00000010 ../PCSC/src/winscard.c:210:SCardEstablishContext() Establishing Context: 0x6CCA300E
00000003 ../PCSC/src/winscard_svc.c:501:ContextThread() ESTABLISH_CONTEXT for client 12, rv=SCARD_S_SUCCESS
00000048 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: CMD_GET_READERS_STATE from client 12
00000049 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: CMD_GET_READERS_STATE from client 12
00000025 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 12
00000004 ../PCSC/src/winscard_svc.c:883:MSGSendReaderStates() Send reader states: 12
00000019 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: CMD_STOP_WAITING_READER_STATE_CHANGE from client 12
00000004 ../PCSC/src/winscard_svc.c:467:ContextThread() CMD_STOP_WAITING_READER_STATE_CHANGE for client 12, rv=SCARD_S_SUCCESS
00000017 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: CONNECT from client 12
00001752 ../PCSC/src/winscard_svc.c:542:ContextThread() Authorized client for 'Nitrokey Nitrokey HSM (XXXXXXXXXXXXXXX         ) 00 00'
00000006 ../PCSC/src/winscard.c:253:SCardConnect() Attempting Connect to Nitrokey Nitrokey HSM (XXXXXXXXXXXXXXX         ) 00 00 using protocol: 3
00000004 ../PCSC/src/readerfactory.c:844:RFReaderInfo() RefReader() count was: 1
00000147 ifdhandler.c:1232:IFDHPowerICC() action: PowerUp, usb:20a0/4230:libudev:0:/dev/bus/usb/002/009 (lun: 0)
02207289 ../PCSC/src/winscard.c:327:SCardConnect() power up complete.
00000032 Card ATR: 3B DE 96 FF 81 91 FE 1F C3 80 31 81 54 48 53 4D 31 73 80 21 40 81 07 92
00000011 ../PCSC/src/winscard.c:347:SCardConnect() powerState: POWER_STATE_IN_USE
00000009 ../PCSC/src/prothandler.c:103:PHSetProtocol() Attempting PTS to T=1
00000011 ifdhandler.c:729:IFDHSetProtocolParameters() protocol T=1, usb:20a0/4230:libudev:0:/dev/bus/usb/002/009 (lun: 0)
00000542 ../PCSC/src/winscard.c:428:SCardConnect() Active Protocol: T=1
00000026 ../PCSC/src/winscard.c:454:SCardConnect() hCard Identity: 1adc292e
00000011 ../PCSC/src/winscard.c:516:SCardConnect() UnrefReader() count was: 2
00000012 ../PCSC/src/winscard_svc.c:562:ContextThread() CONNECT for client 12, rv=SCARD_S_SUCCESS
00000186 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: CONTROL from client 12
00000038 ../PCSC/src/readerfactory.c:871:RFReaderInfoById() RefReader() count was: 1
00000012 ifdhandler.c:1492:IFDHControl() ControlCode: 0x42000D48, usb:20a0/4230:libudev:0:/dev/bus/usb/002/009 (lun: 0)
00000009 Control TxBuffer:
00000010 Control RxBuffer: 12 04 42 33 00 12
00000011 ../PCSC/src/winscard.c:1361:SCardControl() UnrefReader() count was: 2
00000011 ../PCSC/src/winscard_svc.c:784:ContextThread() CONTROL for client 12, rv=SCARD_S_SUCCESS
00000189 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: CONTROL from client 12
00000037 ../PCSC/src/readerfactory.c:871:RFReaderInfoById() RefReader() count was: 1
00000012 ifdhandler.c:1492:IFDHControl() ControlCode: 0x42330012, usb:20a0/4230:libudev:0:/dev/bus/usb/002/009 (lun: 0)
00000009 Control TxBuffer:
00000016 Control RxBuffer: 01 02 00 00 03 01 00 09 01 00 0B 02 A0 20 0C 02 30 42 0A 04 00 00 01 00
00000016 ../PCSC/src/winscard.c:1361:SCardControl() UnrefReader() count was: 2
00000012 ../PCSC/src/winscard_svc.c:784:ContextThread() CONTROL for client 12, rv=SCARD_S_SUCCESS
00000153 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: CONTROL from client 12
00000024 ../PCSC/src/readerfactory.c:871:RFReaderInfoById() RefReader() count was: 1
00000009 ifdhandler.c:1492:IFDHControl() ControlCode: 0x42330012, usb:20a0/4230:libudev:0:/dev/bus/usb/002/009 (lun: 0)
00000009 Control TxBuffer:
00000013 Control RxBuffer: 01 02 00 00 03 01 00 09 01 00 0B 02 A0 20 0C 02 30 42 0A 04 00 00 01 00
00000010 ../PCSC/src/winscard.c:1361:SCardControl() UnrefReader() count was: 2
00000011 ../PCSC/src/winscard_svc.c:784:ContextThread() CONTROL for client 12, rv=SCARD_S_SUCCESS
00000133 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: GET_ATTRIB from client 12
00000024 ../PCSC/src/readerfactory.c:871:RFReaderInfoById() RefReader() count was: 1
00000010 ifdhandler.c:389:IFDHGetCapabilities() tag: 0x10100, usb:20a0/4230:libudev:0:/dev/bus/usb/002/009 (lun: 0)
00000010 ../PCSC/src/winscard.c:1436:SCardGetAttrib() UnrefReader() count was: 2
00000008 ../PCSC/src/winscard_svc.c:813:ContextThread() GET_ATTRIB for client 12, rv=SCARD_S_SUCCESS
00000168 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: GET_ATTRIB from client 12
00000024 ../PCSC/src/readerfactory.c:871:RFReaderInfoById() RefReader() count was: 1
00000010 ifdhandler.c:389:IFDHGetCapabilities() tag: 0x10102, usb:20a0/4230:libudev:0:/dev/bus/usb/002/009 (lun: 0)
00000010 ../PCSC/src/winscard.c:1436:SCardGetAttrib() UnrefReader() count was: 2
00000010 ../PCSC/src/winscard_svc.c:813:ContextThread() GET_ATTRIB for client 12, rv=SCARD_S_SUCCESS
00000094 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: DISCONNECT from client 12
00000023 ../PCSC/src/readerfactory.c:871:RFReaderInfoById() RefReader() count was: 1
00000009 ../PCSC/src/winscard.c:883:SCardDisconnect() Active Contexts: 1
00000010 ../PCSC/src/winscard.c:884:SCardDisconnect() dwDisposition: 0
00000012 ../PCSC/src/winscard.c:1019:SCardDisconnect() powerState: POWER_STATE_GRACE_PERIOD
00000011 ifdhandler.c:389:IFDHGetCapabilities() tag: 0xFB2, usb:20a0/4230:libudev:0:/dev/bus/usb/002/009 (lun: 0)
00000011 ../PCSC/src/winscard.c:1032:SCardDisconnect() Stopping polling thread
00000011 ifdhandler.c:354:IFDHStopPolling() usb:20a0/4230:libudev:0:/dev/bus/usb/002/009 (lun: 0)
00000131 ../PCSC/src/winscard.c:1045:SCardDisconnect() UnrefReader() count was: 2
00000014 ../PCSC/src/winscard_svc.c:599:ContextThread() DISCONNECT for client 12, rv=SCARD_S_SUCCESS
00000217 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 12
00000013 ../PCSC/src/winscard_svc.c:883:MSGSendReaderStates() Send reader states: 12
00001134 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: CMD_STOP_WAITING_READER_STATE_CHANGE from client 12
00000016 ../PCSC/src/winscard_svc.c:467:ContextThread() CMD_STOP_WAITING_READER_STATE_CHANGE for client 12, rv=SCARD_S_SUCCESS
00000098 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 12
00000013 ../PCSC/src/winscard_svc.c:883:MSGSendReaderStates() Send reader states: 12
00000166 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: CMD_STOP_WAITING_READER_STATE_CHANGE from client 12
00000025 ../PCSC/src/winscard_svc.c:467:ContextThread() CMD_STOP_WAITING_READER_STATE_CHANGE for client 12, rv=SCARD_S_SUCCESS
00000144 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: RELEASE_CONTEXT from client 12
00000027 ../PCSC/src/winscard.c:224:SCardReleaseContext() Releasing Context: 0x6CCA300E
00000010 ../PCSC/src/winscard_svc.c:516:ContextThread() RELEASE_CONTEXT for client 12, rv=SCARD_S_SUCCESS
00000100 ../PCSC/src/winscard_svc.c:376:ContextThread() Client die: 12
00000042 ../PCSC/src/winscard_svc.c:1112:MSGCleanupClient() Thread is stopping: dwClientID=12, threadContext @0x56c9e98df8d0
00000019 ../PCSC/src/winscard_svc.c:1120:MSGCleanupClient() Freeing SCONTEXT @0x56c9e98df8d0
00398150 ../PCSC/src/eventhandler.c:492:EHStatusHandlerThread() powerState: POWER_STATE_POWERED
05000751 ifdhandler.c:1232:IFDHPowerICC() action: PowerDown, usb:20a0/4230:libudev:0:/dev/bus/usb/002/009 (lun: 0)
00000268 ../PCSC/src/eventhandler.c:480:EHStatusHandlerThread() powerState: POWER_STATE_UNPOWERED
03422494 ../PCSC/src/winscard_msg_srv.c:253:ProcessEventsServer() Common channel packet arrival
00000013 ../PCSC/src/winscard_msg_srv.c:264:ProcessEventsServer() ProcessCommonChannelRequest detects: 12
00000002 ../PCSC/src/pcscdaemon.c:130:SVCServiceRunLoop() A new context thread creation is requested: 12
00002350 ../PCSC/src/winscard_svc.c:362:ContextThread() Authorized PC/SC client
00000006 ../PCSC/src/winscard_svc.c:365:ContextThread() Thread is started: dwClientID=12, threadContext @0x56c9e98df8d0
00000007 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: CMD_VERSION from client 12
00000005 ../PCSC/src/winscard_svc.c:395:ContextThread() Client is protocol version 4:5
00000002 ../PCSC/src/winscard_svc.c:418:ContextThread() CMD_VERSION for client 12, rv=SCARD_S_SUCCESS
00000076 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: ESTABLISH_CONTEXT from client 12
00000025 ../PCSC/src/winscard.c:210:SCardEstablishContext() Establishing Context: 0x1D7851BC
00000003 ../PCSC/src/winscard_svc.c:501:ContextThread() ESTABLISH_CONTEXT for client 12, rv=SCARD_S_SUCCESS
00000031 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: CMD_GET_READERS_STATE from client 12
00000070 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: CMD_GET_READERS_STATE from client 12
00000081 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 12
00000005 ../PCSC/src/winscard_svc.c:883:MSGSendReaderStates() Send reader states: 12
00000023 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: CMD_STOP_WAITING_READER_STATE_CHANGE from client 12
00000005 ../PCSC/src/winscard_svc.c:467:ContextThread() CMD_STOP_WAITING_READER_STATE_CHANGE for client 12, rv=SCARD_S_SUCCESS
00000022 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: CONNECT from client 12
00001942 ../PCSC/src/winscard_svc.c:542:ContextThread() Authorized client for 'Nitrokey Nitrokey HSM (XXXXXXXXXXXXXXX         ) 00 00'
00000005 ../PCSC/src/winscard.c:253:SCardConnect() Attempting Connect to Nitrokey Nitrokey HSM (XXXXXXXXXXXXXXX         ) 00 00 using protocol: 3
00000004 ../PCSC/src/readerfactory.c:844:RFReaderInfo() RefReader() count was: 1
00000193 ifdhandler.c:1232:IFDHPowerICC() action: PowerUp, usb:20a0/4230:libudev:0:/dev/bus/usb/002/009 (lun: 0)
02209647 ../PCSC/src/winscard.c:327:SCardConnect() power up complete.
00000032 Card ATR: 3B DE 96 FF 81 91 FE 1F C3 80 31 81 54 48 53 4D 31 73 80 21 40 81 07 92
00000010 ../PCSC/src/winscard.c:347:SCardConnect() powerState: POWER_STATE_IN_USE
00000010 ../PCSC/src/prothandler.c:103:PHSetProtocol() Attempting PTS to T=1
00000011 ifdhandler.c:729:IFDHSetProtocolParameters() protocol T=1, usb:20a0/4230:libudev:0:/dev/bus/usb/002/009 (lun: 0)
00000523 ../PCSC/src/winscard.c:428:SCardConnect() Active Protocol: T=1
00000027 ../PCSC/src/winscard.c:454:SCardConnect() hCard Identity: 7980be38
00000010 ../PCSC/src/winscard.c:516:SCardConnect() UnrefReader() count was: 2
00000012 ../PCSC/src/winscard_svc.c:562:ContextThread() CONNECT for client 12, rv=SCARD_S_SUCCESS
00000162 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: CONTROL from client 12
00000035 ../PCSC/src/readerfactory.c:871:RFReaderInfoById() RefReader() count was: 1
00000015 ifdhandler.c:1492:IFDHControl() ControlCode: 0x42000D48, usb:20a0/4230:libudev:0:/dev/bus/usb/002/009 (lun: 0)
00000012 Control TxBuffer:
00000021 Control RxBuffer: 12 04 42 33 00 12
00000016 ../PCSC/src/winscard.c:1361:SCardControl() UnrefReader() count was: 2
00000016 ../PCSC/src/winscard_svc.c:784:ContextThread() CONTROL for client 12, rv=SCARD_S_SUCCESS
00000156 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: CONTROL from client 12
00000033 ../PCSC/src/readerfactory.c:871:RFReaderInfoById() RefReader() count was: 1
00000014 ifdhandler.c:1492:IFDHControl() ControlCode: 0x42330012, usb:20a0/4230:libudev:0:/dev/bus/usb/002/009 (lun: 0)
00000012 Control TxBuffer:
00000037 Control RxBuffer: 01 02 00 00 03 01 00 09 01 00 0B 02 A0 20 0C 02 30 42 0A 04 00 00 01 00
00000016 ../PCSC/src/winscard.c:1361:SCardControl() UnrefReader() count was: 2
00000015 ../PCSC/src/winscard_svc.c:784:ContextThread() CONTROL for client 12, rv=SCARD_S_SUCCESS
00000185 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: CONTROL from client 12
00000034 ../PCSC/src/readerfactory.c:871:RFReaderInfoById() RefReader() count was: 1
00000014 ifdhandler.c:1492:IFDHControl() ControlCode: 0x42330012, usb:20a0/4230:libudev:0:/dev/bus/usb/002/009 (lun: 0)
00000011 Control TxBuffer:
00000021 Control RxBuffer: 01 02 00 00 03 01 00 09 01 00 0B 02 A0 20 0C 02 30 42 0A 04 00 00 01 00
00000018 ../PCSC/src/winscard.c:1361:SCardControl() UnrefReader() count was: 2
00000015 ../PCSC/src/winscard_svc.c:784:ContextThread() CONTROL for client 12, rv=SCARD_S_SUCCESS
00000187 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: GET_ATTRIB from client 12
00000041 ../PCSC/src/readerfactory.c:871:RFReaderInfoById() RefReader() count was: 1
00000020 ifdhandler.c:389:IFDHGetCapabilities() tag: 0x10100, usb:20a0/4230:libudev:0:/dev/bus/usb/002/009 (lun: 0)
00000017 ../PCSC/src/winscard.c:1436:SCardGetAttrib() UnrefReader() count was: 2
00000016 ../PCSC/src/winscard_svc.c:813:ContextThread() GET_ATTRIB for client 12, rv=SCARD_S_SUCCESS
00000164 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: GET_ATTRIB from client 12
00000034 ../PCSC/src/readerfactory.c:871:RFReaderInfoById() RefReader() count was: 1
00000018 ifdhandler.c:389:IFDHGetCapabilities() tag: 0x10102, usb:20a0/4230:libudev:0:/dev/bus/usb/002/009 (lun: 0)
00000015 ../PCSC/src/winscard.c:1436:SCardGetAttrib() UnrefReader() count was: 2
00000013 ../PCSC/src/winscard_svc.c:813:ContextThread() GET_ATTRIB for client 12, rv=SCARD_S_SUCCESS
00000160 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: DISCONNECT from client 12
00000035 ../PCSC/src/readerfactory.c:871:RFReaderInfoById() RefReader() count was: 1
00000016 ../PCSC/src/winscard.c:883:SCardDisconnect() Active Contexts: 1
00000017 ../PCSC/src/winscard.c:884:SCardDisconnect() dwDisposition: 0
00000015 ../PCSC/src/winscard.c:1019:SCardDisconnect() powerState: POWER_STATE_GRACE_PERIOD
00000015 ifdhandler.c:389:IFDHGetCapabilities() tag: 0xFB2, usb:20a0/4230:libudev:0:/dev/bus/usb/002/009 (lun: 0)
00000014 ../PCSC/src/winscard.c:1032:SCardDisconnect() Stopping polling thread
00000014 ifdhandler.c:354:IFDHStopPolling() usb:20a0/4230:libudev:0:/dev/bus/usb/002/009 (lun: 0)
00000121 ../PCSC/src/winscard.c:1045:SCardDisconnect() UnrefReader() count was: 2
00000018 ../PCSC/src/winscard_svc.c:599:ContextThread() DISCONNECT for client 12, rv=SCARD_S_SUCCESS
00000176 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 12
00000017 ../PCSC/src/winscard_svc.c:883:MSGSendReaderStates() Send reader states: 12
00001136 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: CMD_STOP_WAITING_READER_STATE_CHANGE from client 12
00000016 ../PCSC/src/winscard_svc.c:467:ContextThread() CMD_STOP_WAITING_READER_STATE_CHANGE for client 12, rv=SCARD_S_SUCCESS
00000088 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 12
00000017 ../PCSC/src/winscard_svc.c:883:MSGSendReaderStates() Send reader states: 12
00000121 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: CMD_STOP_WAITING_READER_STATE_CHANGE from client 12
00000018 ../PCSC/src/winscard_svc.c:467:ContextThread() CMD_STOP_WAITING_READER_STATE_CHANGE for client 12, rv=SCARD_S_SUCCESS
00000118 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 12
00000017 ../PCSC/src/winscard_svc.c:883:MSGSendReaderStates() Send reader states: 12
00001094 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: CMD_STOP_WAITING_READER_STATE_CHANGE from client 12
00000014 ../PCSC/src/winscard_svc.c:467:ContextThread() CMD_STOP_WAITING_READER_STATE_CHANGE for client 12, rv=SCARD_S_SUCCESS
00000095 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 12
00000019 ../PCSC/src/winscard_svc.c:883:MSGSendReaderStates() Send reader states: 12
00000104 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: CMD_STOP_WAITING_READER_STATE_CHANGE from client 12
00000018 ../PCSC/src/winscard_svc.c:467:ContextThread() CMD_STOP_WAITING_READER_STATE_CHANGE for client 12, rv=SCARD_S_SUCCESS
00000099 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: CONNECT from client 12
00008174 ../PCSC/src/winscard_svc.c:542:ContextThread() Authorized client for 'Nitrokey Nitrokey HSM (XXXXXXXXXXXXXXX         ) 00 00'
00000024 ../PCSC/src/winscard.c:253:SCardConnect() Attempting Connect to Nitrokey Nitrokey HSM (XXXXXXXXXXXXXXX         ) 00 00 using protocol: 3
00000011 ../PCSC/src/readerfactory.c:844:RFReaderInfo() RefReader() count was: 1
00000008 ../PCSC/src/winscard.c:347:SCardConnect() powerState: POWER_STATE_IN_USE
00000009 ../PCSC/src/winscard.c:428:SCardConnect() Active Protocol: T=1
00000011 ../PCSC/src/winscard.c:454:SCardConnect() hCard Identity: 55601d68
00000009 ../PCSC/src/winscard.c:516:SCardConnect() UnrefReader() count was: 2
00000024 ../PCSC/src/winscard_svc.c:562:ContextThread() CONNECT for client 12, rv=SCARD_S_SUCCESS
00000320 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: BEGIN_TRANSACTION from client 12
00000037 ../PCSC/src/readerfactory.c:871:RFReaderInfoById() RefReader() count was: 1
00000018 ../PCSC/src/winscard.c:1084:SCardBeginTransaction() Status: rv=SCARD_S_SUCCESS
00000014 ../PCSC/src/winscard.c:1087:SCardBeginTransaction() UnrefReader() count was: 2
00000017 ../PCSC/src/winscard_svc.c:614:ContextThread() BEGIN_TRANSACTION for client 12, rv=SCARD_S_SUCCESS
00000205 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: TRANSMIT from client 12
00000058 ../PCSC/src/readerfactory.c:871:RFReaderInfoById() RefReader() count was: 1
00000017 ../PCSC/src/winscard.c:1597:SCardTransmit() Send Protocol: T=1
00000022 APDU: 00 A4 04 00 07 62 76 01 FF 00 00 00
00000015 ifdhandler.c:1384:IFDHTransmitToICC() usb:20a0/4230:libudev:0:/dev/bus/usb/002/009 (lun: 0)
12421846 ccid_usb.c:1068:ReadUSB() read failed (2/9): LIBUSB_ERROR_TIMEOUT
00000027 openct/proto-t1.c:212:t1_transceive() fatal: transmit/receive failed
00000018 SW:
00000009 ../PCSC/src/ifdwrapper.c:548:IFDTransmit() Card not transacted: 612
00000009 ../PCSC/src/winscard.c:1622:SCardTransmit() Card not transacted: rv=SCARD_E_NOT_TRANSACTED
00000009 ../PCSC/src/winscard.c:1650:SCardTransmit() UnrefReader() count was: 2
00000019 ../PCSC/src/winscard_svc.c:735:ContextThread() TRANSMIT for client 12, rv=SCARD_E_NOT_TRANSACTED
00000178 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 12
00000022 ../PCSC/src/winscard_svc.c:883:MSGSendReaderStates() Send reader states: 12
00001233 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: CMD_STOP_WAITING_READER_STATE_CHANGE from client 12
00000024 ../PCSC/src/winscard_svc.c:467:ContextThread() CMD_STOP_WAITING_READER_STATE_CHANGE for client 12, rv=SCARD_S_SUCCESS
00000170 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 12
00000021 ../PCSC/src/winscard_svc.c:883:MSGSendReaderStates() Send reader states: 12
00000169 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: CMD_STOP_WAITING_READER_STATE_CHANGE from client 12
00000024 ../PCSC/src/winscard_svc.c:467:ContextThread() CMD_STOP_WAITING_READER_STATE_CHANGE for client 12, rv=SCARD_S_SUCCESS
00000169 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 12
00000025 ../PCSC/src/winscard_svc.c:883:MSGSendReaderStates() Send reader states: 12
00001202 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: CMD_STOP_WAITING_READER_STATE_CHANGE from client 12
00000024 ../PCSC/src/winscard_svc.c:467:ContextThread() CMD_STOP_WAITING_READER_STATE_CHANGE for client 12, rv=SCARD_S_SUCCESS
00000169 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 12
00000020 ../PCSC/src/winscard_svc.c:883:MSGSendReaderStates() Send reader states: 12
00000174 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: CMD_STOP_WAITING_READER_STATE_CHANGE from client 12
00000017 ../PCSC/src/winscard_svc.c:467:ContextThread() CMD_STOP_WAITING_READER_STATE_CHANGE for client 12, rv=SCARD_S_SUCCESS
00000104 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: END_TRANSACTION from client 12
00000035 ../PCSC/src/readerfactory.c:871:RFReaderInfoById() RefReader() count was: 1
00000013 ../PCSC/src/winscard.c:1236:SCardEndTransaction() Status: rv=SCARD_S_SUCCESS
00000012 ../PCSC/src/winscard.c:1239:SCardEndTransaction() UnrefReader() count was: 2
00000014 ../PCSC/src/winscard_svc.c:630:ContextThread() END_TRANSACTION for client 12, rv=SCARD_S_SUCCESS
00000097 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: BEGIN_TRANSACTION from client 12
00000033 ../PCSC/src/readerfactory.c:871:RFReaderInfoById() RefReader() count was: 1
00000012 ../PCSC/src/winscard.c:1084:SCardBeginTransaction() Status: rv=SCARD_S_SUCCESS
00000011 ../PCSC/src/winscard.c:1087:SCardBeginTransaction() UnrefReader() count was: 2
00000014 ../PCSC/src/winscard_svc.c:614:ContextThread() BEGIN_TRANSACTION for client 12, rv=SCARD_S_SUCCESS
00000103 ../PCSC/src/winscard_svc.c:383:ContextThread() Received command: TRANSMIT from client 12
00000045 ../PCSC/src/readerfactory.c:871:RFReaderInfoById() RefReader() count was: 1
00000015 ../PCSC/src/winscard.c:1597:SCardTransmit() Send Protocol: T=1
00000020 APDU: 00 A4 04 00 06 A0 00 00 00 01 01
04996184 ccid_usb.c:961:WriteUSB() write failed (2/9): LIBUSB_ERROR_TIMEOUT
00000035 ../PCSC/src/ifdwrapper.c:369:IFDStatusICC() Card not transacted: 612
00000009 ../PCSC/src/eventhandler.c:334:EHStatusHandlerThread() Error communicating to: Nitrokey Nitrokey HSM (XXXXXXXXXXXXXXX         ) 00 00
00000074 ifdhandler.c:1384:IFDHTransmitToICC() usb:20a0/4230:libudev:0:/dev/bus/usb/002/009 (lun: 0)
00000033 openct/proto-t1.c:168:t1_transceive() T=1 state machine is DEAD. Reset the card first.

eberkhan · June 11, 2025, 8:34am

The issues seen here smell very much like Nitrokey HSM: handle v4.0 smart cards · Issue #100 · Nitrokey/nitrokey-pro-firmware · GitHub related. Scroll down to the findings related to a possibly missing pull-up resistor.