dearsky/pico-hsm
1
0
Fork 0
Code Issues 17 Pull Requests 4 Actions Packages Projects Releases 26 Wiki Activity

Device freeze on device unlock #68

New Issue
Closed
opened 2024-11-28 16:28:14 +08:00 by fastchain · 12 comments
fastchain commented 2024-11-28 16:28:14 +08:00 (Migrated from https://github.com/polhenarejos/pico-hsm)
Copy Link

Board: rpi Pico
pico-hsm version: 5.0

Here are the steps to reproduce the issue:

  1. Initialize the device.

  2. Enable SecureLock.

  3. Unlock the device.

On step 3, the green light starts blinking rapidly, and no further action occurs.

Board: rpi Pico pico-hsm version: 5.0 Here are the steps to reproduce the issue: 1. Initialize the device. 2. Enable SecureLock. 3. Unlock the device. On step 3, the green light starts blinking rapidly, and no further action occurs.
polhenarejos commented 2024-11-28 23:51:46 +08:00 (Migrated from https://github.com/polhenarejos/pico-hsm)
Copy Link

Is it reproducible with pico-hsm-tool?

Is it reproducible with pico-hsm-tool?
fastchain commented 2024-11-29 18:04:37 +08:00 (Migrated from https://github.com/polhenarejos/pico-hsm)
Copy Link

Hi,
No, because the pico-hsm-tool requires a keyring, and I'm on Linux, which doesn't have a compatible keyring. Instead, I use a slightly modified version of the SecureLock2 class :

class SecureLock2:
    def __init__(self, picohsm, secretkey):
        self.picohsm = picohsm
        self.secretkey = secretkey

    def mse(self):
        sk = ec.generate_private_key(ec.SECP256R1())
        pn = sk.public_key().public_numbers()
        self.__pb = sk.public_key().public_bytes(Encoding.X962, PublicFormat.UncompressedPoint)

        ret = self.picohsm.send(cla=0x80, command=0x64, p1=0x3A, p2=0x01, data=list(self.__pb))

        pk = ec.EllipticCurvePublicKey.from_encoded_point(ec.SECP256R1(), bytes(ret))
        shared_key = sk.exchange(ec.ECDH(), pk)

        xkdf = HKDF(
            algorithm=hashes.SHA256(),
            length=12+32,
            salt=None,
            info=self.__pb
        )
        kdf_out = xkdf.derive(shared_key)
        self.__key_enc = kdf_out[12:]
        self.__iv = kdf_out[:12]

    def encrypt_chacha(self, data):
        chacha = ChaCha20Poly1305(self.__key_enc)
        ct = chacha.encrypt(self.__iv, data, self.__pb)
        return ct

    def unlock_device(self):

        ct = self.get_skey()

        self.picohsm.send(cla=0x80, command=0x64, p1=0x3A, p2=0x03, data=list(ct))

    def _get_key_device(self):
        return self.secretkey

    def get_skey(self):
        self.mse()
        ct = self.encrypt_chacha(self._get_key_device())
        return ct

    def enable_device_aut(self):
        ct = self.get_skey()
        self.picohsm.send(cla=0x80, command=0x64, p1=0x3A, p2=0x02, data=list(ct))

    def disable_device_aut(self):
        ct = self.get_skey()
        self.picohsm.send(cla=0x80, command=0x64, p1=0x3A, p2=0x04, p3=list(ct))

The main difference here is that the key is provided as a variable during initialization, rather than being retrieved from a keyring.

I use the following function to initialize the device:

def InitDevice(device_config,force=False):
    device = PicoHSM()
    if len(device.list_keys()) > 2 and force==False:
        print("There are keys on HW. Init procedure stopped.")
        return 0

    device.initialize(pin=device_config.PIN,
                      sopin=device_config.SOPIN,
                      options=device_config.OPTIONS,
                      retries=device_config.RETRIES,
                      dkek_shares=device_config.DKEK_SHARES)

    device.import_dkek(device_config.DKEK)




    curve=ec.SECP256K1
    pkey = ec.derive_private_key(
        int.from_bytes(device_config.SECRET_KEY, byteorder='big'),
        curve(),  # Curve used in Ethereum
        default_backend()
    )
    device_config.KEY_ID = device.import_key(pkey,dkek=device_config.DKEK)
    # pubkey = device.public_key(keyid, param=curve().name)
    device_config.safeConfig(device_config.CONFIGFILENAME)

    #enabling encryption for HSM storage
    slck = SecureLock2(device,device_config.HSM_ACCESS_KEY)
    slck.enable_device_aut()
    slck.unlock_device()

    return device_config

And device_config.HSM_ACCESS_KEY derivation function is

HSM_ACCESS_KEY = secrets.token_bytes(32)

According to tests, key freeze on line

self.picohsm.send(cla=0x80, command=0x64, p1=0x3A, p2=0x03, data=list(ct))

It seems like something had changed in firmware, because works fine with version 3.6.

Hi, No, because the pico-hsm-tool requires a keyring, and I'm on Linux, which doesn't have a compatible keyring. Instead, I use a slightly modified version of the SecureLock2 class : ``` class SecureLock2: def __init__(self, picohsm, secretkey): self.picohsm = picohsm self.secretkey = secretkey def mse(self): sk = ec.generate_private_key(ec.SECP256R1()) pn = sk.public_key().public_numbers() self.__pb = sk.public_key().public_bytes(Encoding.X962, PublicFormat.UncompressedPoint) ret = self.picohsm.send(cla=0x80, command=0x64, p1=0x3A, p2=0x01, data=list(self.__pb)) pk = ec.EllipticCurvePublicKey.from_encoded_point(ec.SECP256R1(), bytes(ret)) shared_key = sk.exchange(ec.ECDH(), pk) xkdf = HKDF( algorithm=hashes.SHA256(), length=12+32, salt=None, info=self.__pb ) kdf_out = xkdf.derive(shared_key) self.__key_enc = kdf_out[12:] self.__iv = kdf_out[:12] def encrypt_chacha(self, data): chacha = ChaCha20Poly1305(self.__key_enc) ct = chacha.encrypt(self.__iv, data, self.__pb) return ct def unlock_device(self): ct = self.get_skey() self.picohsm.send(cla=0x80, command=0x64, p1=0x3A, p2=0x03, data=list(ct)) def _get_key_device(self): return self.secretkey def get_skey(self): self.mse() ct = self.encrypt_chacha(self._get_key_device()) return ct def enable_device_aut(self): ct = self.get_skey() self.picohsm.send(cla=0x80, command=0x64, p1=0x3A, p2=0x02, data=list(ct)) def disable_device_aut(self): ct = self.get_skey() self.picohsm.send(cla=0x80, command=0x64, p1=0x3A, p2=0x04, p3=list(ct)) ``` The main difference here is that the key is provided as a variable during initialization, rather than being retrieved from a keyring. I use the following function to initialize the device: ``` def InitDevice(device_config,force=False): device = PicoHSM() if len(device.list_keys()) > 2 and force==False: print("There are keys on HW. Init procedure stopped.") return 0 device.initialize(pin=device_config.PIN, sopin=device_config.SOPIN, options=device_config.OPTIONS, retries=device_config.RETRIES, dkek_shares=device_config.DKEK_SHARES) device.import_dkek(device_config.DKEK) curve=ec.SECP256K1 pkey = ec.derive_private_key( int.from_bytes(device_config.SECRET_KEY, byteorder='big'), curve(), # Curve used in Ethereum default_backend() ) device_config.KEY_ID = device.import_key(pkey,dkek=device_config.DKEK) # pubkey = device.public_key(keyid, param=curve().name) device_config.safeConfig(device_config.CONFIGFILENAME) #enabling encryption for HSM storage slck = SecureLock2(device,device_config.HSM_ACCESS_KEY) slck.enable_device_aut() slck.unlock_device() return device_config ``` And device_config.HSM_ACCESS_KEY derivation function is ```HSM_ACCESS_KEY = secrets.token_bytes(32)``` According to tests, key freeze on line ``` self.picohsm.send(cla=0x80, command=0x64, p1=0x3A, p2=0x03, data=list(ct)) ``` It seems like something had changed in firmware, because works fine with version 3.6.
polhenarejos commented 2024-11-29 18:32:05 +08:00 (Migrated from https://github.com/polhenarejos/pico-hsm)
Copy Link

Sounds strange. Which board?

Sounds strange. Which board?
fastchain commented 2024-11-29 18:50:50 +08:00 (Migrated from https://github.com/polhenarejos/pico-hsm)
Copy Link

@polhenarejos RPI Pico

@polhenarejos RPI Pico
fastchain commented 2024-11-29 21:21:22 +08:00 (Migrated from https://github.com/polhenarejos/pico-hsm)
Copy Link

@polhenarejos I just ran a sequence of tests (manually disconnecting the device when it froze), and in some cases (approximately 10-20%), it did not freeze.

@polhenarejos I just ran a sequence of tests (manually disconnecting the device when it froze), and in some cases (approximately 10-20%), it did not freeze.
fastchain commented 2024-12-02 23:03:20 +08:00 (Migrated from https://github.com/polhenarejos/pico-hsm)
Copy Link

Here is log from pcsd

hw  | 00008916 eventhandler.c:494:EHStatusHandlerThread() powerState: POWER_STATE_POWERED
hw  | 00172477 winscard_msg_srv.c:256:ProcessEventsServer() Common channel packet arrival
hw  | 00000025 winscard_msg_srv.c:267:ProcessEventsServer() ProcessCommonChannelRequest detects: 15
hw  | 00000001 pcscdaemon.c:133:SVCServiceRunLoop() A new context thread creation is requested: 15
hw  | 00000157 winscard_svc.c:340:ContextThread() Authorized PC/SC client
hw  | 00000016 winscard_svc.c:343:ContextThread() Thread is started: dwClientID=15, threadContext @0x5a05538e8150
hw  | 00000007 winscard_svc.c:361:ContextThread() Received command: CMD_VERSION from client 15
hw  | 00000001 winscard_svc.c:373:ContextThread() Client is protocol version 4:4
hw  | 00000001 winscard_svc.c:396:ContextThread() CMD_VERSION rv=0x0 for client 15
hw  | 00000163 winscard_svc.c:361:ContextThread() Received command: ESTABLISH_CONTEXT from client 15
hw  | 00000005 winscard.c:215:SCardEstablishContext() Establishing Context: 0x7D113133
hw  | 00000001 winscard_svc.c:461:ContextThread() ESTABLISH_CONTEXT rv=0x0 for client 15
hw  | 00000179 winscard_svc.c:361:ContextThread() Received command: CMD_GET_READERS_STATE from client 15
hw  | 00000181 winscard_svc.c:361:ContextThread() Received command: CMD_GET_READERS_STATE from client 15
hw  | 00000130 winscard_svc.c:361:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 15
hw  | 00000005 winscard_svc.c:840:MSGSendReaderStates() Send reader states: 15
hw  | 00000015 winscard_svc.c:361:ContextThread() Received command: CMD_STOP_WAITING_READER_STATE_CHANGE from client 15
hw  | 00000002 winscard_svc.c:442:ContextThread() CMD_STOP_WAITING_READER_STATE_CHANGE rv=0x0 for client 15
hw  | 00000118 winscard_msg_srv.c:256:ProcessEventsServer() Common channel packet arrival
hw  | 00000009 winscard_msg_srv.c:267:ProcessEventsServer() ProcessCommonChannelRequest detects: 16
hw  | 00000002 pcscdaemon.c:133:SVCServiceRunLoop() A new context thread creation is requested: 16
hw  | 00000232 winscard_svc.c:340:ContextThread() Authorized PC/SC client
hw  | 00000017 winscard_svc.c:343:ContextThread() Thread is started: dwClientID=16, threadContext @0x5a0553946960
hw  | 00000013 winscard_svc.c:361:ContextThread() Received command: CMD_VERSION from client 16
hw  | 00000002 winscard_svc.c:373:ContextThread() Client is protocol version 4:4
hw  | 00000001 winscard_svc.c:396:ContextThread() CMD_VERSION rv=0x0 for client 16
hw  | 00000174 winscard_svc.c:361:ContextThread() Received command: ESTABLISH_CONTEXT from client 16
hw  | 00000005 winscard.c:215:SCardEstablishContext() Establishing Context: 0x3F07672A
hw  | 00000002 winscard_svc.c:461:ContextThread() ESTABLISH_CONTEXT rv=0x0 for client 16
hw  | 00000098 winscard_svc.c:361:ContextThread() Received command: CONNECT from client 16
hw  | 00000002 winscard_svc.c:499:ContextThread() Authorized client for 'Yubico YubiKey OTP+FIDO+CCID [Pico Key CCID Interface] (E6612483CB1F932D) 00 00'
hw  | 00000001 winscard.c:258:SCardConnect() Attempting Connect to Yubico YubiKey OTP+FIDO+CCID [Pico Key CCID Interface] (E6612483CB1F932D) 00 00 using protocol: 3
hw  | 00000002 readerfactory.c:825:RFReaderInfo() RefReader() count was: 1
hw  | 00000001 winscard.c:352:SCardConnect() powerState: POWER_STATE_IN_USE
hw  | 00000001 winscard.c:430:SCardConnect() Active Protocol: T=1
hw  | 00000002 winscard.c:456:SCardConnect() hCard Identity: 60f2cf9c
hw  | 00000019 winscard.c:518:SCardConnect() UnrefReader() count was: 2
hw  | 00000002 winscard_svc.c:519:ContextThread() CONNECT rv=0x0 for client 16
hw  | 00000118 winscard_svc.c:361:ContextThread() Received command: TRANSMIT from client 16
hw  | 00000004 readerfactory.c:852:RFReaderInfoById() RefReader() count was: 1
hw  | 00000002 winscard.c:1595:SCardTransmit() Send Protocol: T=1
hw  | 00000001 APDU: 00 A4 04 04 08 A0 58 3F C1 9B 7E 4F 21 00 
hw  | 00000002 ifdhandler.c:1332:IFDHTransmitToICC() usb:1050/0407:libudev:0:/dev/bus/usb/001/060 (lun: 0)
hw  | 00058790 SW: 00 01 07 00 90 00 
hw  | 00000019 winscard.c:1648:SCardTransmit() UnrefReader() count was: 2
hw  | 00000006 winscard_svc.c:691:ContextThread() TRANSMIT rv=0x0 for client 16
hw  | 00000327 winscard_svc.c:361:ContextThread() Received command: TRANSMIT from client 16
hw  | 00000027 readerfactory.c:852:RFReaderInfoById() RefReader() count was: 1
hw  | 00000006 winscard.c:1595:SCardTransmit() Send Protocol: T=1
hw  | 00000010 APDU: 00 A4 04 00 0B E8 2B 06 01 04 01 81 C3 1F 02 01 00 
hw  | 00000202 ifdhandler.c:1332:IFDHTransmitToICC() usb:1050/0407:libudev:0:/dev/bus/usb/001/060 (lun: 0)
hw  | 00059981 SW: 62 22 81 02 00 00 82 01 01 83 02 00 00 84 0B 2B 06 01 04 01 81 C3 1F 02 01 49 8A 01 05 85 05 04 01 FF 05 00 90 00 
hw  | 00000020 winscard.c:1648:SCardTransmit() UnrefReader() count was: 2
hw  | 00000008 winscard_svc.c:691:ContextThread() TRANSMIT rv=0x0 for client 16
hw  | 00000506 winscard_svc.c:361:ContextThread() Received command: TRANSMIT from client 16
hw  | 00000031 readerfactory.c:852:RFReaderInfoById() RefReader() count was: 1
hw  | 00000007 winscard.c:1595:SCardTransmit() Send Protocol: T=1
hw  | 00000009 APDU: 00 B1 2F 02 00 00 04 54 02 00 00 00 00 
hw  | 00000007 ifdhandler.c:1332:IFDHTransmitToICC() usb:1050/0407:libudev:0:/dev/bus/usb/001/060 (lun: 0)
hw  | 00002727 SW: 7F 21 82 01 B6 7F 4E 82 01 6E 5F 29 01 00 42 10 45 53 50 49 43 4F 48 53 4D 54 52 30 30 30 30 31 7F 49 82 01 1D 06 0A 04 00 7F 00 07 02 02 02 02 03 81 20 FF FF FF FF 00 00 00 01 00 00 00 00 00 00 00 00 00 00 00 00 FF FF FF FF FF FF FF FF FF FF FF FF 82 20 FF FF FF FF 00 00 00 01 00 00 00 00 00 00 00 00 00 00 00 00 FF FF FF FF FF FF FF FF FF FF FF FC 83 20 5A C6 35 D8 AA 3A 93 E7 B3 EB BD 55 76 98 86 BC 65 1D 06 B0 CC 53 B0 F6 3B CE 3C 3E 27 D2 60 4B 84 41 04 6B 17 D1 F2 E1 2C 42 47 F8 BC E6 E5 63 A4 40 F2 77 03 7D 81 2D EB 33 A0 F4 A1 39 45 D8 98 C2 96 4F E3 42 E2 FE 1A 7F 9B 8E E7 EB 4A 7C 0F 9E 16 2B CE 33 57 6B 31 5E CE CB B6 40 68 37 BF 51 F5 85 20 FF FF FF FF 00 00 00 00 FF FF FF FF FF FF FF FF BC E6 FA AD A7 17 9E 84 F3 B9 CA C2 FC 63 25 51 86 41 04 87 A2 2C 70 85 CC 7A 28 78 9B C5 E2 28 DF 05 46 CF F9 D7 99 19 5C 15 79 53 6A 6B D0 48 13 05 B7 F4 DE CD EA 81 D5 B5 8E 2B E3 2C F4 41 34 C5 B3 D9 2D D3 B0 A3 92 7D E5 AD 2F 76 94 F2 4F 76 0A 87 01 01 5F 20 10 45 53 50 49 43 4F 48 53 4D 54 52 30 30 30 30 31 7F 4C 0E 06 09 04 00 7F 00 07 03 01 02 02 53 01 00 5F 25 06 02 03 00 03 02 01 5F 24 06 07 00 01 02 03 01 5F 37 40 B5 0B 7A C2 56 97 EC DB 97 BC 91 FF 77 B8 7C 58 80 4E 5F 32 CC F7 06 C8 32 43 76 2A E3 DE 2B 75 69 29 C8 AF 15 0E 7C 9B 3A 7D 1C FC 4F 42 82 08 4E 02 48 8A EB 50 45 88 76 E6 47 B9 82 77 12 CE 7F 21 82 01 B6 7F 4E 82 01 6E 5F 29 01 00 42 10 45 53 50 49 43 4F 48 53 4D 54 52 30 30 30 30 31 7F 49 82 01 1D 06 0A 04 00 7F 00 07 02 02 02 02 03 81 20 FF FF FF FF 00 00 00 01 00 00 00 00 00 00 00 00 00 00 00 00 FF FF FF FF FF FF FF FF FF FF FF FF 82 20 FF FF FF FF 00 00 00 01 00 00 00 00 00 00 00 00 00 00 00 00 FF FF FF FF FF FF FF FF FF FF FF FC 83 20 5A C6 35 D8 AA 3A 93 E7 B3 EB BD 55 76 98 86 BC 65 1D 06 B0 CC 53 B0 F6 3B CE 3C 3E 27 D2 60 4B 84 41 04 6B 17 D1 F2 E1 2C 42 47 F8 BC E6 E5 63 A4 40 F2 77 03 7D 81 2D EB 33 A0 F4 A1 39 45 D8 98 C2 96 4F E3 42 E2 FE 1A 7F 9B 8E E7 EB 4A 7C 0F 9E 16 2B CE 33 57 6B 31 5E CE CB B6 40 68 37 BF 51 F5 85 20 FF FF FF FF 00 00 00 00 FF FF FF FF FF FF FF FF BC E6 FA AD A7 17 9E 84 F3 B9 CA C2 FC 63 25 51 86 41 04 87 A2 2C 70 85 CC 7A 28 78 9B C5 E2 28 DF 05 46 CF F9 D7 99 19 5C 15 79 53 6A 6B D0 48 13 05 B7 F4 DE CD EA 81 D5 B5 8E 2B E3 2C F4 41 34 C5 B3 D9 2D D3 B0 A3 92 7D E5 AD 2F 76 94 F2 4F 76 0A 87 01 01 5F 20 10 45 53 50 49 43 4F 48 53 4D 54 52 30 30 30 30 31 7F 4C 0E 06 09 04 00 7F 00 07 03 01 02 02 53 01 00 5F 25 06 02 03 00 03 02 01 5F 24 06 07 00 01 02 03 01 5F 37 40 B5 0B 7A C2 56 97 EC DB 97 BC 91 FF 77 B8 7C 58 80 4E 5F 32 CC F7 06 C8 32 43 76 2A E3 DE 2B 75 69 29 C8 AF 15 0E 7C 9B 3A 7D 1C FC 4F 42 82 08 4E 02 48 8A EB 50 45 88 76 E6 47 B9 82 77 12 CE 90 00 
hw  | 00000022 winscard.c:1648:SCardTransmit() UnrefReader() count was: 2
hw  | 00000007 winscard_svc.c:691:ContextThread() TRANSMIT rv=0x0 for client 16
hw  | 00000937 winscard_svc.c:361:ContextThread() Received command: TRANSMIT from client 16
hw  | 00000036 readerfactory.c:852:RFReaderInfoById() RefReader() count was: 1
hw  | 00000008 winscard.c:1595:SCardTransmit() Send Protocol: T=1
hw  | 00000010 APDU: 00 20 00 81 00 00 06 36 34 38 32 31 39 00 00 
hw  | 00000009 ifdhandler.c:1332:IFDHTransmitToICC() usb:1050/0407:libudev:0:/dev/bus/usb/001/060 (lun: 0)
hw  | 00083873 SW: 63 C2 
hw  | 00000017 winscard.c:1648:SCardTransmit() UnrefReader() count was: 2
hw  | 00000006 winscard_svc.c:691:ContextThread() TRANSMIT rv=0x0 for client 16
hw  | 00000399 winscard_svc.c:361:ContextThread() Received command: RELEASE_CONTEXT from client 15
hw  | 00000022 winscard.c:229:SCardReleaseContext() Releasing Context: 0x7D113133
hw  | 00000005 winscard_svc.c:476:ContextThread() RELEASE_CONTEXT rv=0x0 for client 15
hw  | 00000228 winscard_svc.c:354:ContextThread() Client die: 15
hw  | 00000038 winscard_svc.c:361:ContextThread() Received command: TRANSMIT from client 16
hw  | 00000001 winscard_svc.c:1061:MSGCleanupClient() Thread is stopping: dwClientID=15, threadContext @0x5a05538e8150
hw  | 00000008 winscard_svc.c:1069:MSGCleanupClient() Freeing SCONTEXT @0x5a05538e8150
hw  | 00000005 readerfactory.c:852:RFReaderInfoById() RefReader() count was: 1
hw  | 00000005 winscard.c:1595:SCardTransmit() Send Protocol: T=1
hw  | 00000003 APDU: 00 58 00 00 00 00 00 
hw  | 00000005 ifdhandler.c:1332:IFDHTransmitToICC() usb:1050/0407:libudev:0:/dev/bus/usb/001/060 (lun: 0)
hw  | 00000859 SW: C4 00 CC 00 CC 01 C4 01 90 00 
hw  | 00000004 winscard.c:1648:SCardTransmit() UnrefReader() count was: 2
hw  | 00000003 winscard_svc.c:691:ContextThread() TRANSMIT rv=0x0 for client 16
hw  | 00000321 winscard_svc.c:361:ContextThread() Received command: TRANSMIT from client 16
hw  | 00000062 readerfactory.c:852:RFReaderInfoById() RefReader() count was: 1
hw  | 00000002 winscard.c:1595:SCardTransmit() Send Protocol: T=1
hw  | 00000009 APDU: 80 50 00 00 00 00 22 80 02 00 01 81 0A 31 32 39 38 35 33 38 38 31 39 82 0A 32 35 36 34 32 32 39 39 36 38 91 01 03 92 01 01 00 00 
hw  | 00000002 ifdhandler.c:1332:IFDHTransmitToICC() usb:1050/0407:libudev:0:/dev/bus/usb/001/060 (lun: 0)
hw  | 00081294 ifdhandler.c:1183:IFDHPowerICC() action: PowerDown, usb:1050/0407:libudev:1:/dev/bus/usb/001/060 (lun: 10000)
hw  | 00000706 eventhandler.c:482:EHStatusHandlerThread() powerState: POWER_STATE_UNPOWERED
hw  | 01309325 SW: 90 00 
hw  | 00000020 winscard.c:1648:SCardTransmit() UnrefReader() count was: 2
hw  | 00000006 winscard_svc.c:691:ContextThread() TRANSMIT rv=0x0 for client 16
hw  | 00000394 winscard_svc.c:361:ContextThread() Received command: TRANSMIT from client 16
hw  | 00000025 readerfactory.c:852:RFReaderInfoById() RefReader() count was: 1
hw  | 00000005 winscard.c:1595:SCardTransmit() Send Protocol: T=1
hw  | 00000009 APDU: 80 52 00 00 00 00 20 74 C4 6D 31 F0 45 C4 F8 CD F5 1A 7D 80 6A B2 0A 83 17 B8 7B 63 82 A5 25 D7 89 81 EC 57 52 CE A0 00 00 
hw  | 00000005 ifdhandler.c:1332:IFDHTransmitToICC() usb:1050/0407:libudev:0:/dev/bus/usb/001/060 (lun: 0)
hw  | 00165294 SW: 01 00 D9 A0 01 4C E7 57 87 15 90 00 
hw  | 00000019 winscard.c:1648:SCardTransmit() UnrefReader() count was: 2
hw  | 00000005 winscard_svc.c:691:ContextThread() TRANSMIT rv=0x0 for client 16
hw  | 00006856 winscard_svc.c:361:ContextThread() Received command: TRANSMIT from client 16
hw  | 00000006 readerfactory.c:852:RFReaderInfoById() RefReader() count was: 1
hw  | 00000001 winscard.c:1595:SCardTransmit() Send Protocol: T=1
hw  | 00000001 APDU: 00 58 00 00 00 00 00 
hw  | 00000001 ifdhandler.c:1332:IFDHTransmitToICC() usb:1050/0407:libudev:0:/dev/bus/usb/001/060 (lun: 0)
hw  | 00000545 SW: C4 00 CC 00 90 00 
hw  | 00000002 winscard.c:1648:SCardTransmit() UnrefReader() count was: 2
hw  | 00000001 winscard_svc.c:691:ContextThread() TRANSMIT rv=0x0 for client 16
hw  | 00000053 winscard_svc.c:361:ContextThread() Received command: TRANSMIT from client 16
hw  | 00000003 readerfactory.c:852:RFReaderInfoById() RefReader() count was: 1
hw  | 00000001 winscard.c:1595:SCardTransmit() Send Protocol: T=1
hw  | 00000018 APDU: 80 74 01 93 00 01 6B D9 A0 01 4C E7 57 87 15 0C 00 0A 04 00 7F 00 07 02 02 02 02 03 00 00 00 00 00 00 B8 1E F6 B2 91 E6 CB 75 17 AD B2 AF AC E6 E7 6B 2D AB 32 60 3E EF 71 3D 19 3F A6 D2 C5 80 1A 88 17 87 35 66 C7 8C FE 4D 5E E0 D4 C5 56 C4 AA 83 2F 29 5B BB 49 DA A0 DA 33 02 E0 81 9E 96 68 2B 49 63 1F 64 7B 61 D6 F3 C5 09 84 5A 18 A3 D1 48 4D 39 AB AC C8 BC 30 18 4B 90 14 A7 85 BF A6 28 D8 15 89 18 A3 C4 30 21 CB EA E9 24 32 6F B5 03 62 2F F1 A4 1D 48 CF FE 7A 1F 32 D8 77 3B A3 60 D5 0F BF B7 59 70 30 05 2A A6 85 B2 10 31 9C 48 20 7A FF 41 53 20 8A E3 B2 43 62 62 64 B7 07 AB 01 FE B9 6E 90 5C AE 96 4C 96 A7 DF 1C 16 45 F8 53 91 34 A0 62 62 A4 80 E2 3F 7F 15 A0 76 F2 42 22 ED 3F 95 D7 BD 40 39 21 46 F4 4E 4A 29 16 C4 05 BE 01 5F 77 58 EC 27 FE 5F B3 B3 D7 B7 A3 C7 39 E8 53 0A 48 2F F9 EF 7F 73 DD 42 28 D3 E9 3C EF C5 46 89 B5 10 1E 15 AA EE 11 24 8C AD 44 26 CF D8 7C D7 2F F7 A3 33 2D 64 1E 18 9E 0E B1 CF 7B 25 8A 12 A1 12 35 ED AD 98 E0 04 CB EF 50 DF 1E F3 49 ED 7C F2 8F 28 28 CD 04 53 35 EC 55 79 CF B4 04 F4 42 BF 27 1D EE DC 9B 1E 6B F1 FD 67 8A 2A CA 52 0A 25 68 31 DA F6 9F 0A 43 DD 9B EF 00 00 
hw  | 00000005 ifdhandler.c:1332:IFDHTransmitToICC() usb:1050/0407:libudev:0:/dev/bus/usb/001/060 (lun: 0)
hw  | 00910898 SW: 90 00 
hw  | 00000015 winscard.c:1648:SCardTransmit() UnrefReader() count was: 2
hw  | 00000005 winscard_svc.c:691:ContextThread() TRANSMIT rv=0x0 for client 16
hw  | 00001108 winscard_svc.c:361:ContextThread() Received command: TRANSMIT from client 16
hw  | 00000018 readerfactory.c:852:RFReaderInfoById() RefReader() count was: 1
hw  | 00000004 winscard.c:1595:SCardTransmit() Send Protocol: T=1
hw  | 00000010 APDU: 80 64 3A 01 00 00 41 04 9E 51 A8 9D 8D 27 27 E5 BB 2B B0 55 3A 00 15 54 B0 D6 84 1D C6 FE 5F 74 CE DC 82 CB 8F C8 66 50 28 14 C3 39 FD 86 ED 2A 66 F1 22 72 64 80 0D 36 29 AE CB 06 28 99 21 D4 1C C8 2C A1 0B 55 A0 62 00 00 
hw  | 00000003 ifdhandler.c:1332:IFDHTransmitToICC() usb:1050/0407:libudev:0:/dev/bus/usb/001/060 (lun: 0)
hw  | 00587109 SW: 04 2E E8 1A 8C 1D 8A A5 03 B2 4E F7 41 36 1B 2A 61 FC 25 96 00 EF 0E 16 D6 86 5D BC 94 0D 9B 92 AE FF 85 B5 84 76 34 9D 7A AD 5E 57 EC E0 36 59 FB 71 7F C2 BB 57 58 12 B6 24 61 27 F1 AF A2 54 BB 90 00 
hw  | 00000018 winscard.c:1648:SCardTransmit() UnrefReader() count was: 2
hw  | 00000007 winscard_svc.c:691:ContextThread() TRANSMIT rv=0x0 for client 16
hw  | 00001524 winscard_svc.c:361:ContextThread() Received command: TRANSMIT from client 16
hw  | 00000016 readerfactory.c:852:RFReaderInfoById() RefReader() count was: 1
hw  | 00000005 winscard.c:1595:SCardTransmit() Send Protocol: T=1
hw  | 00000014 APDU: 80 64 3A 02 00 00 30 72 BA 54 32 22 55 94 57 13 31 61 9F FB CC B9 43 7C BB 29 11 23 82 99 4A 1A CD F0 9A 0B 6C 85 0B 44 59 AB 1E BD C9 36 21 E7 80 C1 EE 34 50 BC 7F 00 00 
hw  | 00000005 ifdhandler.c:1332:IFDHTransmitToICC() usb:1050/0407:libudev:0:/dev/bus/usb/001/060 (lun: 0)
hw  | 00121383 SW: 90 00 
hw  | 00000020 winscard.c:1648:SCardTransmit() UnrefReader() count was: 2
hw  | 00000006 winscard_svc.c:691:ContextThread() TRANSMIT rv=0x0 for client 16
hw  | 00000504 winscard_svc.c:361:ContextThread() Received command: TRANSMIT from client 16
hw  | 00000024 readerfactory.c:852:RFReaderInfoById() RefReader() count was: 1
hw  | 00000004 winscard.c:1595:SCardTransmit() Send Protocol: T=1
hw  | 00000014 APDU: 80 64 3A 01 00 00 41 04 49 7B AD 8E 60 E3 8A 3A B5 7E 41 F3 AA A0 B3 6F 8B FE BC 5C F8 3C 81 A9 1A 8B 31 1C EE 08 31 18 4E E1 52 36 7F C4 FC 89 6C 11 EB 03 46 70 A2 71 24 C0 7B 3C 5B 41 14 D0 3E 61 CE 40 10 FE B6 42 00 00 
hw  | 00000005 ifdhandler.c:1332:IFDHTransmitToICC() usb:1050/0407:libudev:0:/dev/bus/usb/001/060 (lun: 0)
hw  | 00581424 SW: 04 EA CE 81 6A 8B 0F C4 A2 41 79 7D D9 18 D7 DF 2F ED 5F D2 BE 4D 90 76 CC 9E 67 30 9D 55 64 F2 59 ED 95 8F 58 5B D2 AF AB F6 40 85 99 EE AE 2C FC BE E9 E6 01 0C FE 7F 90 FD 41 83 34 96 FD 35 A4 90 00 
hw  | 00000022 winscard.c:1648:SCardTransmit() UnrefReader() count was: 2
hw  | 00000013 winscard_svc.c:691:ContextThread() TRANSMIT rv=0x0 for client 16
hw  | 00001049 winscard_svc.c:361:ContextThread() Received command: TRANSMIT from client 16
hw  | 00000023 readerfactory.c:852:RFReaderInfoById() RefReader() count was: 1
hw  | 00000005 winscard.c:1595:SCardTransmit() Send Protocol: T=1
hw  | 00000012 APDU: 80 64 3A 03 00 00 30 B8 37 22 69 BE D6 39 12 11 4D E3 C7 A2 C3 02 4D A2 BE 45 60 D4 AF AE F1 A8 F4 3C 27 D2 3B CB C4 A4 46 08 06 FD 6E 3D BB 36 CD 0C 06 92 D5 6F 19 00 00 
hw  | 00000004 ifdhandler.c:1332:IFDHTransmitToICC() usb:1050/0407:libudev:0:/dev/bus/usb/001/060 (lun: 0)

this is a log of init + unlock procedure until the freeze

Here is log from ```pcsd``` ``` hw | 00008916 eventhandler.c:494:EHStatusHandlerThread() powerState: POWER_STATE_POWERED hw | 00172477 winscard_msg_srv.c:256:ProcessEventsServer() Common channel packet arrival hw | 00000025 winscard_msg_srv.c:267:ProcessEventsServer() ProcessCommonChannelRequest detects: 15 hw | 00000001 pcscdaemon.c:133:SVCServiceRunLoop() A new context thread creation is requested: 15 hw | 00000157 winscard_svc.c:340:ContextThread() Authorized PC/SC client hw | 00000016 winscard_svc.c:343:ContextThread() Thread is started: dwClientID=15, threadContext @0x5a05538e8150 hw | 00000007 winscard_svc.c:361:ContextThread() Received command: CMD_VERSION from client 15 hw | 00000001 winscard_svc.c:373:ContextThread() Client is protocol version 4:4 hw | 00000001 winscard_svc.c:396:ContextThread() CMD_VERSION rv=0x0 for client 15 hw | 00000163 winscard_svc.c:361:ContextThread() Received command: ESTABLISH_CONTEXT from client 15 hw | 00000005 winscard.c:215:SCardEstablishContext() Establishing Context: 0x7D113133 hw | 00000001 winscard_svc.c:461:ContextThread() ESTABLISH_CONTEXT rv=0x0 for client 15 hw | 00000179 winscard_svc.c:361:ContextThread() Received command: CMD_GET_READERS_STATE from client 15 hw | 00000181 winscard_svc.c:361:ContextThread() Received command: CMD_GET_READERS_STATE from client 15 hw | 00000130 winscard_svc.c:361:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 15 hw | 00000005 winscard_svc.c:840:MSGSendReaderStates() Send reader states: 15 hw | 00000015 winscard_svc.c:361:ContextThread() Received command: CMD_STOP_WAITING_READER_STATE_CHANGE from client 15 hw | 00000002 winscard_svc.c:442:ContextThread() CMD_STOP_WAITING_READER_STATE_CHANGE rv=0x0 for client 15 hw | 00000118 winscard_msg_srv.c:256:ProcessEventsServer() Common channel packet arrival hw | 00000009 winscard_msg_srv.c:267:ProcessEventsServer() ProcessCommonChannelRequest detects: 16 hw | 00000002 pcscdaemon.c:133:SVCServiceRunLoop() A new context thread creation is requested: 16 hw | 00000232 winscard_svc.c:340:ContextThread() Authorized PC/SC client hw | 00000017 winscard_svc.c:343:ContextThread() Thread is started: dwClientID=16, threadContext @0x5a0553946960 hw | 00000013 winscard_svc.c:361:ContextThread() Received command: CMD_VERSION from client 16 hw | 00000002 winscard_svc.c:373:ContextThread() Client is protocol version 4:4 hw | 00000001 winscard_svc.c:396:ContextThread() CMD_VERSION rv=0x0 for client 16 hw | 00000174 winscard_svc.c:361:ContextThread() Received command: ESTABLISH_CONTEXT from client 16 hw | 00000005 winscard.c:215:SCardEstablishContext() Establishing Context: 0x3F07672A hw | 00000002 winscard_svc.c:461:ContextThread() ESTABLISH_CONTEXT rv=0x0 for client 16 hw | 00000098 winscard_svc.c:361:ContextThread() Received command: CONNECT from client 16 hw | 00000002 winscard_svc.c:499:ContextThread() Authorized client for 'Yubico YubiKey OTP+FIDO+CCID [Pico Key CCID Interface] (E6612483CB1F932D) 00 00' hw | 00000001 winscard.c:258:SCardConnect() Attempting Connect to Yubico YubiKey OTP+FIDO+CCID [Pico Key CCID Interface] (E6612483CB1F932D) 00 00 using protocol: 3 hw | 00000002 readerfactory.c:825:RFReaderInfo() RefReader() count was: 1 hw | 00000001 winscard.c:352:SCardConnect() powerState: POWER_STATE_IN_USE hw | 00000001 winscard.c:430:SCardConnect() Active Protocol: T=1 hw | 00000002 winscard.c:456:SCardConnect() hCard Identity: 60f2cf9c hw | 00000019 winscard.c:518:SCardConnect() UnrefReader() count was: 2 hw | 00000002 winscard_svc.c:519:ContextThread() CONNECT rv=0x0 for client 16 hw | 00000118 winscard_svc.c:361:ContextThread() Received command: TRANSMIT from client 16 hw | 00000004 readerfactory.c:852:RFReaderInfoById() RefReader() count was: 1 hw | 00000002 winscard.c:1595:SCardTransmit() Send Protocol: T=1 hw | 00000001 APDU: 00 A4 04 04 08 A0 58 3F C1 9B 7E 4F 21 00 hw | 00000002 ifdhandler.c:1332:IFDHTransmitToICC() usb:1050/0407:libudev:0:/dev/bus/usb/001/060 (lun: 0) hw | 00058790 SW: 00 01 07 00 90 00 hw | 00000019 winscard.c:1648:SCardTransmit() UnrefReader() count was: 2 hw | 00000006 winscard_svc.c:691:ContextThread() TRANSMIT rv=0x0 for client 16 hw | 00000327 winscard_svc.c:361:ContextThread() Received command: TRANSMIT from client 16 hw | 00000027 readerfactory.c:852:RFReaderInfoById() RefReader() count was: 1 hw | 00000006 winscard.c:1595:SCardTransmit() Send Protocol: T=1 hw | 00000010 APDU: 00 A4 04 00 0B E8 2B 06 01 04 01 81 C3 1F 02 01 00 hw | 00000202 ifdhandler.c:1332:IFDHTransmitToICC() usb:1050/0407:libudev:0:/dev/bus/usb/001/060 (lun: 0) hw | 00059981 SW: 62 22 81 02 00 00 82 01 01 83 02 00 00 84 0B 2B 06 01 04 01 81 C3 1F 02 01 49 8A 01 05 85 05 04 01 FF 05 00 90 00 hw | 00000020 winscard.c:1648:SCardTransmit() UnrefReader() count was: 2 hw | 00000008 winscard_svc.c:691:ContextThread() TRANSMIT rv=0x0 for client 16 hw | 00000506 winscard_svc.c:361:ContextThread() Received command: TRANSMIT from client 16 hw | 00000031 readerfactory.c:852:RFReaderInfoById() RefReader() count was: 1 hw | 00000007 winscard.c:1595:SCardTransmit() Send Protocol: T=1 hw | 00000009 APDU: 00 B1 2F 02 00 00 04 54 02 00 00 00 00 hw | 00000007 ifdhandler.c:1332:IFDHTransmitToICC() usb:1050/0407:libudev:0:/dev/bus/usb/001/060 (lun: 0) hw | 00002727 SW: 7F 21 82 01 B6 7F 4E 82 01 6E 5F 29 01 00 42 10 45 53 50 49 43 4F 48 53 4D 54 52 30 30 30 30 31 7F 49 82 01 1D 06 0A 04 00 7F 00 07 02 02 02 02 03 81 20 FF FF FF FF 00 00 00 01 00 00 00 00 00 00 00 00 00 00 00 00 FF FF FF FF FF FF FF FF FF FF FF FF 82 20 FF FF FF FF 00 00 00 01 00 00 00 00 00 00 00 00 00 00 00 00 FF FF FF FF FF FF FF FF FF FF FF FC 83 20 5A C6 35 D8 AA 3A 93 E7 B3 EB BD 55 76 98 86 BC 65 1D 06 B0 CC 53 B0 F6 3B CE 3C 3E 27 D2 60 4B 84 41 04 6B 17 D1 F2 E1 2C 42 47 F8 BC E6 E5 63 A4 40 F2 77 03 7D 81 2D EB 33 A0 F4 A1 39 45 D8 98 C2 96 4F E3 42 E2 FE 1A 7F 9B 8E E7 EB 4A 7C 0F 9E 16 2B CE 33 57 6B 31 5E CE CB B6 40 68 37 BF 51 F5 85 20 FF FF FF FF 00 00 00 00 FF FF FF FF FF FF FF FF BC E6 FA AD A7 17 9E 84 F3 B9 CA C2 FC 63 25 51 86 41 04 87 A2 2C 70 85 CC 7A 28 78 9B C5 E2 28 DF 05 46 CF F9 D7 99 19 5C 15 79 53 6A 6B D0 48 13 05 B7 F4 DE CD EA 81 D5 B5 8E 2B E3 2C F4 41 34 C5 B3 D9 2D D3 B0 A3 92 7D E5 AD 2F 76 94 F2 4F 76 0A 87 01 01 5F 20 10 45 53 50 49 43 4F 48 53 4D 54 52 30 30 30 30 31 7F 4C 0E 06 09 04 00 7F 00 07 03 01 02 02 53 01 00 5F 25 06 02 03 00 03 02 01 5F 24 06 07 00 01 02 03 01 5F 37 40 B5 0B 7A C2 56 97 EC DB 97 BC 91 FF 77 B8 7C 58 80 4E 5F 32 CC F7 06 C8 32 43 76 2A E3 DE 2B 75 69 29 C8 AF 15 0E 7C 9B 3A 7D 1C FC 4F 42 82 08 4E 02 48 8A EB 50 45 88 76 E6 47 B9 82 77 12 CE 7F 21 82 01 B6 7F 4E 82 01 6E 5F 29 01 00 42 10 45 53 50 49 43 4F 48 53 4D 54 52 30 30 30 30 31 7F 49 82 01 1D 06 0A 04 00 7F 00 07 02 02 02 02 03 81 20 FF FF FF FF 00 00 00 01 00 00 00 00 00 00 00 00 00 00 00 00 FF FF FF FF FF FF FF FF FF FF FF FF 82 20 FF FF FF FF 00 00 00 01 00 00 00 00 00 00 00 00 00 00 00 00 FF FF FF FF FF FF FF FF FF FF FF FC 83 20 5A C6 35 D8 AA 3A 93 E7 B3 EB BD 55 76 98 86 BC 65 1D 06 B0 CC 53 B0 F6 3B CE 3C 3E 27 D2 60 4B 84 41 04 6B 17 D1 F2 E1 2C 42 47 F8 BC E6 E5 63 A4 40 F2 77 03 7D 81 2D EB 33 A0 F4 A1 39 45 D8 98 C2 96 4F E3 42 E2 FE 1A 7F 9B 8E E7 EB 4A 7C 0F 9E 16 2B CE 33 57 6B 31 5E CE CB B6 40 68 37 BF 51 F5 85 20 FF FF FF FF 00 00 00 00 FF FF FF FF FF FF FF FF BC E6 FA AD A7 17 9E 84 F3 B9 CA C2 FC 63 25 51 86 41 04 87 A2 2C 70 85 CC 7A 28 78 9B C5 E2 28 DF 05 46 CF F9 D7 99 19 5C 15 79 53 6A 6B D0 48 13 05 B7 F4 DE CD EA 81 D5 B5 8E 2B E3 2C F4 41 34 C5 B3 D9 2D D3 B0 A3 92 7D E5 AD 2F 76 94 F2 4F 76 0A 87 01 01 5F 20 10 45 53 50 49 43 4F 48 53 4D 54 52 30 30 30 30 31 7F 4C 0E 06 09 04 00 7F 00 07 03 01 02 02 53 01 00 5F 25 06 02 03 00 03 02 01 5F 24 06 07 00 01 02 03 01 5F 37 40 B5 0B 7A C2 56 97 EC DB 97 BC 91 FF 77 B8 7C 58 80 4E 5F 32 CC F7 06 C8 32 43 76 2A E3 DE 2B 75 69 29 C8 AF 15 0E 7C 9B 3A 7D 1C FC 4F 42 82 08 4E 02 48 8A EB 50 45 88 76 E6 47 B9 82 77 12 CE 90 00 hw | 00000022 winscard.c:1648:SCardTransmit() UnrefReader() count was: 2 hw | 00000007 winscard_svc.c:691:ContextThread() TRANSMIT rv=0x0 for client 16 hw | 00000937 winscard_svc.c:361:ContextThread() Received command: TRANSMIT from client 16 hw | 00000036 readerfactory.c:852:RFReaderInfoById() RefReader() count was: 1 hw | 00000008 winscard.c:1595:SCardTransmit() Send Protocol: T=1 hw | 00000010 APDU: 00 20 00 81 00 00 06 36 34 38 32 31 39 00 00 hw | 00000009 ifdhandler.c:1332:IFDHTransmitToICC() usb:1050/0407:libudev:0:/dev/bus/usb/001/060 (lun: 0) hw | 00083873 SW: 63 C2 hw | 00000017 winscard.c:1648:SCardTransmit() UnrefReader() count was: 2 hw | 00000006 winscard_svc.c:691:ContextThread() TRANSMIT rv=0x0 for client 16 hw | 00000399 winscard_svc.c:361:ContextThread() Received command: RELEASE_CONTEXT from client 15 hw | 00000022 winscard.c:229:SCardReleaseContext() Releasing Context: 0x7D113133 hw | 00000005 winscard_svc.c:476:ContextThread() RELEASE_CONTEXT rv=0x0 for client 15 hw | 00000228 winscard_svc.c:354:ContextThread() Client die: 15 hw | 00000038 winscard_svc.c:361:ContextThread() Received command: TRANSMIT from client 16 hw | 00000001 winscard_svc.c:1061:MSGCleanupClient() Thread is stopping: dwClientID=15, threadContext @0x5a05538e8150 hw | 00000008 winscard_svc.c:1069:MSGCleanupClient() Freeing SCONTEXT @0x5a05538e8150 hw | 00000005 readerfactory.c:852:RFReaderInfoById() RefReader() count was: 1 hw | 00000005 winscard.c:1595:SCardTransmit() Send Protocol: T=1 hw | 00000003 APDU: 00 58 00 00 00 00 00 hw | 00000005 ifdhandler.c:1332:IFDHTransmitToICC() usb:1050/0407:libudev:0:/dev/bus/usb/001/060 (lun: 0) hw | 00000859 SW: C4 00 CC 00 CC 01 C4 01 90 00 hw | 00000004 winscard.c:1648:SCardTransmit() UnrefReader() count was: 2 hw | 00000003 winscard_svc.c:691:ContextThread() TRANSMIT rv=0x0 for client 16 hw | 00000321 winscard_svc.c:361:ContextThread() Received command: TRANSMIT from client 16 hw | 00000062 readerfactory.c:852:RFReaderInfoById() RefReader() count was: 1 hw | 00000002 winscard.c:1595:SCardTransmit() Send Protocol: T=1 hw | 00000009 APDU: 80 50 00 00 00 00 22 80 02 00 01 81 0A 31 32 39 38 35 33 38 38 31 39 82 0A 32 35 36 34 32 32 39 39 36 38 91 01 03 92 01 01 00 00 hw | 00000002 ifdhandler.c:1332:IFDHTransmitToICC() usb:1050/0407:libudev:0:/dev/bus/usb/001/060 (lun: 0) hw | 00081294 ifdhandler.c:1183:IFDHPowerICC() action: PowerDown, usb:1050/0407:libudev:1:/dev/bus/usb/001/060 (lun: 10000) hw | 00000706 eventhandler.c:482:EHStatusHandlerThread() powerState: POWER_STATE_UNPOWERED hw | 01309325 SW: 90 00 hw | 00000020 winscard.c:1648:SCardTransmit() UnrefReader() count was: 2 hw | 00000006 winscard_svc.c:691:ContextThread() TRANSMIT rv=0x0 for client 16 hw | 00000394 winscard_svc.c:361:ContextThread() Received command: TRANSMIT from client 16 hw | 00000025 readerfactory.c:852:RFReaderInfoById() RefReader() count was: 1 hw | 00000005 winscard.c:1595:SCardTransmit() Send Protocol: T=1 hw | 00000009 APDU: 80 52 00 00 00 00 20 74 C4 6D 31 F0 45 C4 F8 CD F5 1A 7D 80 6A B2 0A 83 17 B8 7B 63 82 A5 25 D7 89 81 EC 57 52 CE A0 00 00 hw | 00000005 ifdhandler.c:1332:IFDHTransmitToICC() usb:1050/0407:libudev:0:/dev/bus/usb/001/060 (lun: 0) hw | 00165294 SW: 01 00 D9 A0 01 4C E7 57 87 15 90 00 hw | 00000019 winscard.c:1648:SCardTransmit() UnrefReader() count was: 2 hw | 00000005 winscard_svc.c:691:ContextThread() TRANSMIT rv=0x0 for client 16 hw | 00006856 winscard_svc.c:361:ContextThread() Received command: TRANSMIT from client 16 hw | 00000006 readerfactory.c:852:RFReaderInfoById() RefReader() count was: 1 hw | 00000001 winscard.c:1595:SCardTransmit() Send Protocol: T=1 hw | 00000001 APDU: 00 58 00 00 00 00 00 hw | 00000001 ifdhandler.c:1332:IFDHTransmitToICC() usb:1050/0407:libudev:0:/dev/bus/usb/001/060 (lun: 0) hw | 00000545 SW: C4 00 CC 00 90 00 hw | 00000002 winscard.c:1648:SCardTransmit() UnrefReader() count was: 2 hw | 00000001 winscard_svc.c:691:ContextThread() TRANSMIT rv=0x0 for client 16 hw | 00000053 winscard_svc.c:361:ContextThread() Received command: TRANSMIT from client 16 hw | 00000003 readerfactory.c:852:RFReaderInfoById() RefReader() count was: 1 hw | 00000001 winscard.c:1595:SCardTransmit() Send Protocol: T=1 hw | 00000018 APDU: 80 74 01 93 00 01 6B D9 A0 01 4C E7 57 87 15 0C 00 0A 04 00 7F 00 07 02 02 02 02 03 00 00 00 00 00 00 B8 1E F6 B2 91 E6 CB 75 17 AD B2 AF AC E6 E7 6B 2D AB 32 60 3E EF 71 3D 19 3F A6 D2 C5 80 1A 88 17 87 35 66 C7 8C FE 4D 5E E0 D4 C5 56 C4 AA 83 2F 29 5B BB 49 DA A0 DA 33 02 E0 81 9E 96 68 2B 49 63 1F 64 7B 61 D6 F3 C5 09 84 5A 18 A3 D1 48 4D 39 AB AC C8 BC 30 18 4B 90 14 A7 85 BF A6 28 D8 15 89 18 A3 C4 30 21 CB EA E9 24 32 6F B5 03 62 2F F1 A4 1D 48 CF FE 7A 1F 32 D8 77 3B A3 60 D5 0F BF B7 59 70 30 05 2A A6 85 B2 10 31 9C 48 20 7A FF 41 53 20 8A E3 B2 43 62 62 64 B7 07 AB 01 FE B9 6E 90 5C AE 96 4C 96 A7 DF 1C 16 45 F8 53 91 34 A0 62 62 A4 80 E2 3F 7F 15 A0 76 F2 42 22 ED 3F 95 D7 BD 40 39 21 46 F4 4E 4A 29 16 C4 05 BE 01 5F 77 58 EC 27 FE 5F B3 B3 D7 B7 A3 C7 39 E8 53 0A 48 2F F9 EF 7F 73 DD 42 28 D3 E9 3C EF C5 46 89 B5 10 1E 15 AA EE 11 24 8C AD 44 26 CF D8 7C D7 2F F7 A3 33 2D 64 1E 18 9E 0E B1 CF 7B 25 8A 12 A1 12 35 ED AD 98 E0 04 CB EF 50 DF 1E F3 49 ED 7C F2 8F 28 28 CD 04 53 35 EC 55 79 CF B4 04 F4 42 BF 27 1D EE DC 9B 1E 6B F1 FD 67 8A 2A CA 52 0A 25 68 31 DA F6 9F 0A 43 DD 9B EF 00 00 hw | 00000005 ifdhandler.c:1332:IFDHTransmitToICC() usb:1050/0407:libudev:0:/dev/bus/usb/001/060 (lun: 0) hw | 00910898 SW: 90 00 hw | 00000015 winscard.c:1648:SCardTransmit() UnrefReader() count was: 2 hw | 00000005 winscard_svc.c:691:ContextThread() TRANSMIT rv=0x0 for client 16 hw | 00001108 winscard_svc.c:361:ContextThread() Received command: TRANSMIT from client 16 hw | 00000018 readerfactory.c:852:RFReaderInfoById() RefReader() count was: 1 hw | 00000004 winscard.c:1595:SCardTransmit() Send Protocol: T=1 hw | 00000010 APDU: 80 64 3A 01 00 00 41 04 9E 51 A8 9D 8D 27 27 E5 BB 2B B0 55 3A 00 15 54 B0 D6 84 1D C6 FE 5F 74 CE DC 82 CB 8F C8 66 50 28 14 C3 39 FD 86 ED 2A 66 F1 22 72 64 80 0D 36 29 AE CB 06 28 99 21 D4 1C C8 2C A1 0B 55 A0 62 00 00 hw | 00000003 ifdhandler.c:1332:IFDHTransmitToICC() usb:1050/0407:libudev:0:/dev/bus/usb/001/060 (lun: 0) hw | 00587109 SW: 04 2E E8 1A 8C 1D 8A A5 03 B2 4E F7 41 36 1B 2A 61 FC 25 96 00 EF 0E 16 D6 86 5D BC 94 0D 9B 92 AE FF 85 B5 84 76 34 9D 7A AD 5E 57 EC E0 36 59 FB 71 7F C2 BB 57 58 12 B6 24 61 27 F1 AF A2 54 BB 90 00 hw | 00000018 winscard.c:1648:SCardTransmit() UnrefReader() count was: 2 hw | 00000007 winscard_svc.c:691:ContextThread() TRANSMIT rv=0x0 for client 16 hw | 00001524 winscard_svc.c:361:ContextThread() Received command: TRANSMIT from client 16 hw | 00000016 readerfactory.c:852:RFReaderInfoById() RefReader() count was: 1 hw | 00000005 winscard.c:1595:SCardTransmit() Send Protocol: T=1 hw | 00000014 APDU: 80 64 3A 02 00 00 30 72 BA 54 32 22 55 94 57 13 31 61 9F FB CC B9 43 7C BB 29 11 23 82 99 4A 1A CD F0 9A 0B 6C 85 0B 44 59 AB 1E BD C9 36 21 E7 80 C1 EE 34 50 BC 7F 00 00 hw | 00000005 ifdhandler.c:1332:IFDHTransmitToICC() usb:1050/0407:libudev:0:/dev/bus/usb/001/060 (lun: 0) hw | 00121383 SW: 90 00 hw | 00000020 winscard.c:1648:SCardTransmit() UnrefReader() count was: 2 hw | 00000006 winscard_svc.c:691:ContextThread() TRANSMIT rv=0x0 for client 16 hw | 00000504 winscard_svc.c:361:ContextThread() Received command: TRANSMIT from client 16 hw | 00000024 readerfactory.c:852:RFReaderInfoById() RefReader() count was: 1 hw | 00000004 winscard.c:1595:SCardTransmit() Send Protocol: T=1 hw | 00000014 APDU: 80 64 3A 01 00 00 41 04 49 7B AD 8E 60 E3 8A 3A B5 7E 41 F3 AA A0 B3 6F 8B FE BC 5C F8 3C 81 A9 1A 8B 31 1C EE 08 31 18 4E E1 52 36 7F C4 FC 89 6C 11 EB 03 46 70 A2 71 24 C0 7B 3C 5B 41 14 D0 3E 61 CE 40 10 FE B6 42 00 00 hw | 00000005 ifdhandler.c:1332:IFDHTransmitToICC() usb:1050/0407:libudev:0:/dev/bus/usb/001/060 (lun: 0) hw | 00581424 SW: 04 EA CE 81 6A 8B 0F C4 A2 41 79 7D D9 18 D7 DF 2F ED 5F D2 BE 4D 90 76 CC 9E 67 30 9D 55 64 F2 59 ED 95 8F 58 5B D2 AF AB F6 40 85 99 EE AE 2C FC BE E9 E6 01 0C FE 7F 90 FD 41 83 34 96 FD 35 A4 90 00 hw | 00000022 winscard.c:1648:SCardTransmit() UnrefReader() count was: 2 hw | 00000013 winscard_svc.c:691:ContextThread() TRANSMIT rv=0x0 for client 16 hw | 00001049 winscard_svc.c:361:ContextThread() Received command: TRANSMIT from client 16 hw | 00000023 readerfactory.c:852:RFReaderInfoById() RefReader() count was: 1 hw | 00000005 winscard.c:1595:SCardTransmit() Send Protocol: T=1 hw | 00000012 APDU: 80 64 3A 03 00 00 30 B8 37 22 69 BE D6 39 12 11 4D E3 C7 A2 C3 02 4D A2 BE 45 60 D4 AF AE F1 A8 F4 3C 27 D2 3B CB C4 A4 46 08 06 FD 6E 3D BB 36 CD 0C 06 92 D5 6F 19 00 00 hw | 00000004 ifdhandler.c:1332:IFDHTransmitToICC() usb:1050/0407:libudev:0:/dev/bus/usb/001/060 (lun: 0) ``` this is a log of init + unlock procedure until the freeze
polhenarejos commented 2024-12-03 03:00:58 +08:00 (Migrated from https://github.com/polhenarejos/pico-hsm)
Copy Link

Here's the problem:

hw  | 00000012 APDU: 80 64 3A 03 00 00 30 B8 37 22 69 BE D6 39 12 11 4D E3 C7 A2 C3 02 4D A2 BE 45 60 D4 AF AE F1 A8 F4 3C 27 D2 3B CB C4 A4 46 08 06 FD 6E 3D BB 36 CD 0C 06 92 D5 6F 19 00 00

You are sending an encrypted key of 48 bytes, but it must be 32 bytes. I guess that HSM_ACCESS_KEY = secrets.token_bytes(32) does not return 32 bytes, but 48. Check it.

Here's the problem: ``` hw | 00000012 APDU: 80 64 3A 03 00 00 30 B8 37 22 69 BE D6 39 12 11 4D E3 C7 A2 C3 02 4D A2 BE 45 60 D4 AF AE F1 A8 F4 3C 27 D2 3B CB C4 A4 46 08 06 FD 6E 3D BB 36 CD 0C 06 92 D5 6F 19 00 00 ``` You are sending an encrypted key of 48 bytes, but it must be 32 bytes. I guess that `HSM_ACCESS_KEY = secrets.token_bytes(32)` does not return 32 bytes, but 48. Check it.
fastchain commented 2024-12-03 08:52:32 +08:00 (Migrated from https://github.com/polhenarejos/pico-hsm)
Copy Link

@polhenarejos
According to specs and tests it returns exactly 32 bytes

Python 3.12.4 (main, Jun  7 2024, 06:33:07) [GCC 14.1.1 20240522] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> import secrets
>>> len(secrets.token_bytes(32))
32
>>> secrets.token_bytes(32)
b'\xfe\x8aZ96R\xd7\xbd:\xa3\x94L\xc7\xa4\x10\xa4\x96\xf7O\xc5\xfb\xeb\x12\x1b\xf5\x84\xf4\xb0E\x9f\xd7<'
>>>

https://docs.python.org/3/library/secrets.html

I might be mistaken, but it’s unclear how the ciphertext could be 32 bytes, considering the encryption process involves an IV as shown in this section of the code.

@polhenarejos According to specs and tests it returns exactly 32 bytes ``` Python 3.12.4 (main, Jun 7 2024, 06:33:07) [GCC 14.1.1 20240522] on linux Type "help", "copyright", "credits" or "license" for more information. >>> import secrets >>> len(secrets.token_bytes(32)) 32 >>> secrets.token_bytes(32) b'\xfe\x8aZ96R\xd7\xbd:\xa3\x94L\xc7\xa4\x10\xa4\x96\xf7O\xc5\xfb\xeb\x12\x1b\xf5\x84\xf4\xb0E\x9f\xd7<' >>> ``` https://docs.python.org/3/library/secrets.html I might be mistaken, but it’s unclear how the ciphertext could be 32 bytes, considering the encryption process involves an IV as shown in [this section of the code](https://github.com/polhenarejos/pico-hsm/blob/master/tools/pico-hsm-tool.py#L320-L343).
polhenarejos commented 2024-12-03 15:37:06 +08:00 (Migrated from https://github.com/polhenarejos/pico-hsm)
Copy Link

There was a buffer overflow in the code and it has been fixed.

You can test it tomorrow with nightly development build or build it yourself.

There was a buffer overflow in the code and it has been fixed. You can test it tomorrow with nightly development build or build it yourself.
fastchain commented 2024-12-03 16:06:22 +08:00 (Migrated from https://github.com/polhenarejos/pico-hsm)
Copy Link

@polhenarejos

Many thanks! By the way, which versions should be set to build from the nightly with this command

sudo docker build \                                                                             
    --build-arg VERSION_PICO_SDK=2.0.0 \
    --build-arg VERSION_MAJOR=5 \
    --build-arg VERSION_MINOR=0 \
    --build-arg PICO_BOARD=pico  \
    --build-arg USB_VID=0x.. \
    --build-arg USB_PID=0x.. \
    -t pico-hsm-builder . --no-cache

?

@polhenarejos Many thanks! By the way, which versions should be set to build from the nightly with this command ``` sudo docker build \ --build-arg VERSION_PICO_SDK=2.0.0 \ --build-arg VERSION_MAJOR=5 \ --build-arg VERSION_MINOR=0 \ --build-arg PICO_BOARD=pico \ --build-arg USB_VID=0x.. \ --build-arg USB_PID=0x.. \ -t pico-hsm-builder . --no-cache ``` ?
polhenarejos commented 2024-12-03 16:30:43 +08:00 (Migrated from https://github.com/polhenarejos/pico-hsm)
Copy Link

Nightly builds are built automatically during the midnight. So you can wait until tomorrow and download a fresh built.

If you prefer not waiting, then you can build it. development branch uses Pico SDK 2.1.0.

Nightly builds are built automatically during the midnight. So you can wait until tomorrow and download a fresh built. If you prefer not waiting, then you can build it. `development` branch uses Pico SDK 2.1.0.
fastchain commented 2024-12-03 18:03:54 +08:00 (Migrated from https://github.com/polhenarejos/pico-hsm)
Copy Link

@polhenarejos Thanks. Just tested: initialization with SecureLock and unlock works smoothly. But there is problem with further use. I created a new ticket https://github.com/polhenarejos/pico-hsm/issues/69

@polhenarejos Thanks. Just tested: initialization with SecureLock and unlock works smoothly. But there is problem with further use. I created a new ticket https://github.com/polhenarejos/pico-hsm/issues/69
Sign in to join this conversation.
No Branch/Tag Specified
Branches Tags
Labels
Clear labels
bug
Something isn't working
 bug
Something isn't working
 dependencies
Pull requests that update a dependency file
 dependencies
Pull requests that update a dependency file
 documentation
Improvements or additions to documentation
 documentation
Improvements or additions to documentation
 duplicate
This issue or pull request already exists
 duplicate
This issue or pull request already exists
 enhancement
New feature or request
 enhancement
New feature or request
 good first issue
Good for newcomers
 good first issue
Good for newcomers
 help wanted
Extra attention is needed
 help wanted
Extra attention is needed
 invalid
This doesn't seem right
 invalid
This doesn't seem right
 question
Further information is requested
 question
Further information is requested
 wontfix
This will not be worked on
 wontfix
This will not be worked on
No Label
Milestone
No items
No Milestone
Projects
Clear projects
No project
Assignees
Clear assignees
dearsky
No Assignees
1 Participants
Notifications
Due Date
No due date set.
Dependencies

No dependencies set.

Reference: dearsky/pico-hsm#68
Delete Branch "%!s()"

Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?