Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Resetting library state #3018

Closed
arrowd opened this issue Feb 6, 2024 · 23 comments · Fixed by #3024
Closed

Resetting library state #3018

arrowd opened this issue Feb 6, 2024 · 23 comments · Fixed by #3024

Comments

@arrowd
Copy link

arrowd commented Feb 6, 2024

I'm writing a daemon-like application that runs for a long time and make calls to OpenSC via both PKCS11 API and the internal one (sc_*). I know that I shouldn't really use sc_* stuff, but the bug I'm going to explain here can also be reproduced with pure C_* functions.

The core of the problem is OpenSC seems to cache quite a lot of stuff and there is no way to tell it to "reload". This can be illustrated with the following example:

$ opensc-explorer
OpenSC [3F00]> cat 005e
00000000: 61 73 64 61 73 64 00 asdasd.
OpenSC [3F00]> erase
OpenSC [3F00]> cat 005e
00000000: 61 73 64 61 73 64 00 asdasd.
OpenSC [3F00]> ^D
$ opensc-explorer
OpenSC Explorer version 0.24.0
Using reader with a card: Nitrokey Nitrokey 3 [CCID/ICCD Interface] 00 00
OpenSC [3F00]> cat 005e

As you can see, the erase command actually cleared out the 3F00/005e EF, but this change can't be seen by the library until I restart the program (read: reinitialize the library).

A related example with PKCS11 API is following:

  1. Generate a key pair
    CK_MECHANISM mechanism = {CKM_RSA_PKCS_KEY_PAIR_GEN, NULL_PTR, 0};
    CK_ULONG modulusBits = 2048;
    CK_BBOOL _true = TRUE;
    CK_BBOOL _false = FALSE;
    CK_OBJECT_CLASS pubkey_class = CKO_PUBLIC_KEY;
    CK_OBJECT_CLASS privkey_class = CKO_PRIVATE_KEY;
    CK_ATTRIBUTE publicKeyTemplate[20] = {
        {CKA_CLASS, &pubkey_class, sizeof(pubkey_class)},
        {CKA_TOKEN, &_true, sizeof(_true)},
        {CKA_PRIVATE, &_false, sizeof(_false)},
        {CKA_MODULUS_BITS, &modulusBits, sizeof(modulusBits)},
    };
    int n_pubkey_attr = 4;
    CK_ATTRIBUTE privateKeyTemplate[20] = {
        {CKA_CLASS, &privkey_class, sizeof(privkey_class)},
        {CKA_TOKEN, &_true, sizeof(_true)},
        {CKA_PRIVATE, &_true, sizeof(_true)},
        {CKA_SENSITIVE, &_true, sizeof(_true)},
    };
    int n_privkey_attr = 4;

    rv = m_p11->C_GenerateKeyPair(m_sessionHandle, &mechanism,
                                    publicKeyTemplate, n_pubkey_attr,
                                    privateKeyTemplate, n_privkey_attr,
                                    &hPublicKey, &hPrivateKey);
  1. Output a modulus:
    CK_BBOOL _true = TRUE;
    CK_ATTRIBUTE attrs[] =
    {
        { CKA_ENCRYPT, &_true, sizeof(_true)},
    };
    auto rv = m_p11->C_FindObjectsInit(m_sessionHandle, attrs, sizeof(attrs) / sizeof(CK_ATTRIBUTE));
    if (rv != CKR_OK) {
...
    }

    CK_OBJECT_HANDLE key;
    CK_ULONG outSize;
    rv = m_p11->C_FindObjects(m_sessionHandle, &key, 1, &outSize);
    m_p11->C_FindObjectsFinal(m_sessionHandle);

    CK_ATTRIBUTE attr = { CK_MODULUS, NULL, 0 };
    rv = m_p11->C_GetAttributeValue(m_sessionHandle, object, &attr, 1);
    if (rv != CKR_OK) {
...
    }
    if (attr.ulValueLen == -1u)
        ...

    QByteArray ret(attr.ulValueLen + 1, 0);

    attr.pValue = ret.data();
    if (!attr.pValue)
        ...

    rv = m_p11->C_GetAttributeValue(m_sessionHandle, object, &attr, 1);
    if (attr.ulValueLen == -1u)
        ...
  1. Generate a key pair again using the same code as in step 1.
  2. Output a modulus again with the code from step 2. It outputs the same byte array, despite the fact that key pair is changed.
  3. Restart the program
  4. Output a modulus third time and now it is different from the previous two calls.

Running pkcs11-tool or openpgp-tool between steps 4 and 5 confirms that keys are actually changed on-card, it is just the application doesn't see the change.

To sum this up, I need to trigger the same reloading/recaching process inside the library as when the token is physically reattached to the host. Or am I fundametally missing something?

@dengert
Copy link
Member

dengert commented Feb 6, 2024

Or am I fundametally missing something?

C_Finalize? then C_Initialize? or maybe C_CloseAllSessions

May need to turn off in opensc.conf use_file_caching

@arrowd
Copy link
Author

arrowd commented Feb 6, 2024

I have only one session in my application and closing/opening it does not fix the problem.

C_Finalize will probably work, but the problem there is that it will also shutdown other readers, which might be in process of doing something.

I'll try your suggestion regarding use_file_caching option, thanks!

@dengert
Copy link
Member

dengert commented Feb 7, 2024

C_Finalize will probably work, but the problem there is that it will also shutdown other readers, which might be in process of doing something.

The PKCS11 module is loaded and run within a process. The PCSC pcscd provides a list of readers and locking so multiple processes can "share" readers and cards. Calling C_Finalize in your process at most would only effect any reader where you have a session. It should not effect any other processes. See the man opensc.conf Configuration of PC/SC Readers The leave options says don't do anything to changes the login state or power state of the card. SCardBeginTransaction and SCardEndTransaction hold and release the PCSC lock when not connected in exclusive mode.

For more info, Google for: SCardBeginTransaction

The other problem you may be seeing is the card driver and pkcs15 layers may not be updating the pkcs11 data when you update or delete an object. C_CloseAllSessions may take care of that, but using C_finalize would.

What card are you using?

@arrowd
Copy link
Author

arrowd commented Feb 7, 2024

Calling C_Finalize in your process at most would only effect any reader where you have a session. It should not effect any other processes.

Yes, this is what I'm talking about. My application may be working with several readers simultaneously and C_Finalize will terminate sessions for all of them. I only need to reload one at time.

May need to turn off in opensc.conf use_file_caching

I tried that and it didn't work. Here's the debugging output when reproducing the problem via opensc-explorer.

The first call (no cache present):

card.c:471:sc_lock: called
reader-pcsc.c:690:pcsc_lock: called
card-openpgp.c:3726:pgp_card_reader_lock_obtained: called
card-openpgp.c:3753:pgp_card_reader_lock_obtained: returning with: 0 (Success)
card.c:513:sc_lock: returning with: 0 (Success)
card.c:850:sc_select_file: called; type=2, path=3f00005e
card-openpgp.c:1447:pgp_select_file: called
card.c:893:sc_get_data: called, tag=005e
card-openpgp.c:1826:pgp_get_data: called
apdu.c:550:sc_transmit_apdu: called
card.c:471:sc_lock: called
card.c:513:sc_lock: returning with: 0 (Success)
apdu.c:515:sc_transmit: called
apdu.c:363:sc_single_transmit: called
apdu.c:370:sc_single_transmit: CLA:0, INS:CA, P1:0, P2:5E, data(0) 0x0
reader-pcsc.c:325:pcsc_transmit: reader 'Nitrokey Nitrokey 3 [CCID/ICCD Interface] 00 00'
reader-pcsc.c:326:pcsc_transmit: 
Outgoing APDU (7 bytes):
00 CA 00 5E 00 20 00 ...^. .

reader-pcsc.c:244:pcsc_internal_transmit: called
reader-pcsc.c:335:pcsc_transmit: 
Incoming APDU (8 bytes):
61 73 64 61 73 64 90 00 asdasd..

apdu.c:382:sc_single_transmit: returning with: 0 (Success)
apdu.c:539:sc_transmit: returning with: 0 (Success)
card.c:523:sc_unlock: called
card-openpgp.c:1853:pgp_get_data: returning with: 6
card.c:898:sc_get_data: returning with: 6
card-openpgp.c:1511:pgp_select_file: returning with: 0 (Success)
card.c:885:sc_select_file: returning with: 0 (Success)
card.c:523:sc_unlock: called
reader-pcsc.c:742:pcsc_unlock: called
card.c:471:sc_lock: called
reader-pcsc.c:690:pcsc_lock: called
card-openpgp.c:3726:pgp_card_reader_lock_obtained: called
card-openpgp.c:3753:pgp_card_reader_lock_obtained: returning with: 0 (Success)
card.c:513:sc_lock: returning with: 0 (Success)
card.c:630:sc_read_binary: called; 6 bytes at index 0
card.c:471:sc_lock: called
card.c:513:sc_lock: returning with: 0 (Success)
card-openpgp.c:1586:pgp_read_binary: called
card-openpgp.c:1607:pgp_read_binary: returning with: 6
card.c:523:sc_unlock: called
card.c:678:sc_read_binary: returning with: 6
card.c:523:sc_unlock: called
reader-pcsc.c:742:pcsc_unlock: called
00000000: 61 73 64 61 73 64 asdasd
card.c:471:sc_lock: called
reader-pcsc.c:690:pcsc_lock: called
card-openpgp.c:3726:pgp_card_reader_lock_obtained: called
card-openpgp.c:3753:pgp_card_reader_lock_obtained: returning with: 0 (Success)
card.c:513:sc_lock: returning with: 0 (Success)
card.c:850:sc_select_file: called; type=2, path=3f00
card-openpgp.c:1447:pgp_select_file: called
card-openpgp.c:1511:pgp_select_file: returning with: 0 (Success)
card.c:885:sc_select_file: returning with: 0 (Success)
card.c:523:sc_unlock: called
reader-pcsc.c:742:pcsc_unlock: called

Then I do erase and cat 005e again. Now it is cached:

card.c:471:sc_lock: called
reader-pcsc.c:690:pcsc_lock: called
card-openpgp.c:3726:pgp_card_reader_lock_obtained: called
card-openpgp.c:3753:pgp_card_reader_lock_obtained: returning with: 0 (Success)
card.c:513:sc_lock: returning with: 0 (Success)
card.c:850:sc_select_file: called; type=2, path=3f00005e
card-openpgp.c:1447:pgp_select_file: called
card-openpgp.c:1511:pgp_select_file: returning with: 0 (Success)
card.c:885:sc_select_file: returning with: 0 (Success)
card.c:523:sc_unlock: called
reader-pcsc.c:742:pcsc_unlock: called
card.c:471:sc_lock: called
reader-pcsc.c:690:pcsc_lock: called
card-openpgp.c:3726:pgp_card_reader_lock_obtained: called
card-openpgp.c:3753:pgp_card_reader_lock_obtained: returning with: 0 (Success)
card.c:513:sc_lock: returning with: 0 (Success)
card.c:630:sc_read_binary: called; 6 bytes at index 0
card.c:471:sc_lock: called
card.c:513:sc_lock: returning with: 0 (Success)
card-openpgp.c:1586:pgp_read_binary: called
card-openpgp.c:1607:pgp_read_binary: returning with: 6
card.c:523:sc_unlock: called
card.c:678:sc_read_binary: returning with: 6
card.c:523:sc_unlock: called
reader-pcsc.c:742:pcsc_unlock: called
00000000: 61 73 64 61 73 64 asdasd
card.c:471:sc_lock: called
reader-pcsc.c:690:pcsc_lock: called
card-openpgp.c:3726:pgp_card_reader_lock_obtained: called
card-openpgp.c:3753:pgp_card_reader_lock_obtained: returning with: 0 (Success)
card.c:513:sc_lock: returning with: 0 (Success)
card.c:850:sc_select_file: called; type=2, path=3f00
card-openpgp.c:1447:pgp_select_file: called
card-openpgp.c:1511:pgp_select_file: returning with: 0 (Success)
card.c:885:sc_select_file: returning with: 0 (Success)
card.c:523:sc_unlock: called
reader-pcsc.c:742:pcsc_unlock: called

We can see that pgp_select_file shortcuts in the second case

card-openpgp.c:1447:pgp_select_file: called
card-openpgp.c:1511:pgp_select_file: returning with: 0 (Success)

but it goes down to sc_get_data->pgp_get_data in the first case:

card-openpgp.c:1447:pgp_select_file: called
card.c:893:sc_get_data: called, tag=005e
card-openpgp.c:1826:pgp_get_data: called

This code path doesn't even look at the use_file_caching config variable, which is why setting it doesn't fix the problem for me.

What card are you using?

Nitrokey 3C NFC, which gets recognized as a generic OpenPGP card.

I will now try a hackish solution - to fool pcsc_wait_for_event into thinking that the card was detached/attach, basically triggering the reload code path for a single reader.

If you have idea how to properly fix this on OpenSC, I'm also open to suggestions and ready to do the work.

@arrowd
Copy link
Author

arrowd commented Feb 7, 2024

For more info, Google for: SCardBeginTransaction

Ah, missed that part. It brought me to transaction_end_action = reset and transaction_end_action = unpower options in the config, but they didn't help either.

@dengert
Copy link
Member

dengert commented Feb 7, 2024

From OpenPGP Smart Card Application V3.4.1

It looks like you are trying to change the openpgp DO:

5E S 0 – max. Login data (binary, proprietary) 

This DO can be used to store any information used for
the Log-In process in a client/server authentication
(e.g. user name of a network). The maximum length of
this DO is announced in Extended Capabilities.

but not by going through the card-openpgp.c or pkcs15-openpgp.c where this may have been cached.

An opensc debug log would show if DO 0053 was read.

This is similar to DO 0101 accept to write DO 0101, PW1 is needed, but to write 005E PW3 is needed.
See "Access conditions for Data Objects:"

See comments:
https://github.com/OpenSC/OpenSC/blob/master/src/pkcs15init/pkcs15-openpgp.c#L487-L497

It appears OpenSC can not update any of the DOs: Name (5B), Language preference (5F2D), or Sex (5F35).
It would be nice if these could be treated as PKCS11 data objects along with 005E.

I assume you are not using pkcs11 to initialize the card. If you are then in ./framework-pkcs15.c pkcs15_initialize calls card_removed followed by card_detect_all which I think does what you need.

All of the following could work with any card, not just openpgp:

  • pkcs11-base-v3.0-os section "5.4.5 C_GetInterfaceList" define a new profile, that will return a vendor provided function that can call card_removed followed by card_detect_all

  • Using a vendor callback function pkcs11-base-v3.0-os section "5.21.2 Vendor-defined callbacks" is a possibility.

  • Define a CKO_VENDOR_DEFINED object. Find the object, then call C_SetAttributeValue with a vendor define attribute. OpenSC defines 3 of these in pkcs11.h

#define SC_VENDOR_DEFINED 0x4F534300  /* OSC */
#define CKA_OPENSC_NON_REPUDIATION      (CKA_VENDOR_DEFINED | SC_VENDOR_DEFINED | 1UL)
#define CKA_SPKI			(CKA_VENDOR_DEFINED | SC_VENDOR_DEFINED | 2UL)
#define CKA_OPENSC_ALWAYS_AUTH_ANY_OBJECT (CKA_VENDOR_DEFINED | SC_VENDOR_DEFINED | 3UL)

C_SetAttributeValue which would then cause the calls to card_removed followed by card_detect_all

All of the above would work with any card that needs to refresh its data .

Not an easy problem to solve. I like the CKO_VENDOR_DEFINED object.

@arrowd
Copy link
Author

arrowd commented Feb 7, 2024

But the problem is not specific to pkcs15 DOs. PKCS11 data objects are also not being refreshed, see my example with consecutive C_GenerateKeyPair calls.

@dengert
Copy link
Member

dengert commented Feb 7, 2024

Either of these problems have to be fixed in the openpgp software or as suggeste4d above or via card_removed followed by card_detect_all.

Or you remove the card after doing the updates and reinsert if you need to continue.

Or if you can find some other package that can handle the 005E and generating keys

Or you do the login mapping from what is on the card in the login software without having to use the 005E.

It is still not clear what your long running daemon is trying to do and why it is allowed to modify the card.

You can submit also submit a PR.

@arrowd
Copy link
Author

arrowd commented Feb 7, 2024

card_removed followed by card_detect_all.

Is it guaranteed that CK_SLOT_ID for the given reader will stay same after this?

@dengert
Copy link
Member

dengert commented Feb 7, 2024

Is it guaranteed that CK_SLOT_ID for the given reader will stay same after this?

The commands are used from C_initToken after the token is initialize so you get the data from the token. The token appears as if it was physically removed but the reader is still there. The application then has to go looking for it again. So you could identify the token from the CK_TOKEN_INFO label and/or serialnumber assuming you have not changed them.

The same code is used if the token was physically removed and reinserted. (Physical removal may also remove the reader is part of the token.) The code make no assumption that the token has not been modified or it is same token being inserted. PKCS11 does not keep track of the time between removal and reinsertion. But you are guaranteed that when you find it again, you are now looking at data from the card, and not cached in the driver. (But OpenSC might be caching files in you home directory, so make sure it is off.)

@dengert
Copy link
Member

dengert commented Feb 8, 2024

@arrowd You had said the generate keypair had the same problem. But your examples does not include a CKA_ID or CKA_LABEL .

Please have a look at gen_keypair which adds CKA_ID and CKA_LABEL at https://github.com/OpenSC/OpenSC/blob/master/src/tools/pkcs11-tool.c#L3101-L3117

So it is not clear what key was generated.

Also note pkcs11-tool also has a delete object which you may have to call first to delete any existing key or other other object.
https://github.com/OpenSC/OpenSC/blob/master/src/tools/pkcs11-tool.c#L5873-L5933

Also note that specific applets like openpgp only support specific CKA _ID values of 01, 02 and 03. for keys.

If you can git around this issue with keys, it might be possible to add code to handle updating the 005E via pkcs11.

OpenSC spy and debug logs would be helpful.

@dengert
Copy link
Member

dengert commented Feb 8, 2024

Another option for your daemon is to start a subprocess to do required operations, passing the token label or serial number.
The subprocess could use OpenSC commands pkcs11-tool, pkcs15-init, pkcs15-tool ... or even gpg-card command.

Using a Nitro start test card, previously initialized by GnuPG's gpg-card:

$/opt/gnupg/bin/gpg-card 
Reader ...........: Nitrokey Nitrokey Start (FSIJ-1.2.15-43123355) 00 00
Card type ........: gnuk
Serial number ....: D276000124010200FFFE001233550000
Application type .: OpenPGP
Version ..........: 2.0
Displayed s/n ....: FFFE 00123355
Manufacturer .....: unmanaged S/N range (fffe)
Name of cardholder: Doug (Nitro Start) Engert
Language prefs ...: [not set]
Salutation .......: 
URL of public key : [not set]
Login data .......: [not set]
Signature PIN ....: forced
Max. PIN lengths .: 127 127 127
PIN retry counter : 3 3 3
Signature counter : 3
Capabilities .....: key-import algo-change button
KDF setting ......: off
UIF setting ......: Sign=off Decrypt=off Auth=off
Signature key ....: 197E8B0440CF7D29162CB309A661FF6F4AB1C147
      keyref .....: OPENPGP.1  (sign,cert)
      algorithm ..: ed25519
      stored fpr .: 30541B420157F83AB50C1D7F753DD3A9B8B020A8
      created ....: 2023-11-25 14:01:02
Encryption key....: 71557B88E8EFA40D9B42D754AA131B9A213B5ACE
      keyref .....: OPENPGP.2  (encr)
      algorithm ..: cv25519
      stored fpr .: 86F038E093ECD060C6FA90760AE68AFC59ED5A30
      created ....: 2023-11-25 14:01:30
Authentication key: 96888FABE6E9BC75480D6E792AD10FC63D83C2FC
      keyref .....: OPENPGP.3  (sign,auth)
      algorithm ..: rsa2048
      stored fpr .: 82B309B19C4F096E96609BD6510A76CB6CF75B59
      created ....: 2023-11-25 13:52:44
gpg/card> login
Login data (account name): Doug
gpg/card> list
Reader ...........: Nitrokey Nitrokey Start (FSIJ-1.2.15-43123355) 00 00
Card type ........: gnuk
Serial number ....: D276000124010200FFFE001233550000
Application type .: OpenPGP
Version ..........: 2.0
Displayed s/n ....: FFFE 00123355
Manufacturer .....: unmanaged S/N range (fffe)
Name of cardholder: Doug (Nitro Start) Engert
Language prefs ...: [not set]
Salutation .......: 
URL of public key : [not set]
Login data .......: [not set]
Signature PIN ....: forced
Max. PIN lengths .: 127 127 127
PIN retry counter : 3 3 3
Signature counter : 3
Capabilities .....: key-import algo-change button
KDF setting ......: off
UIF setting ......: Sign=off Decrypt=off Auth=off
Signature key ....: 197E8B0440CF7D29162CB309A661FF6F4AB1C147
      keyref .....: OPENPGP.1  (sign,cert)
      algorithm ..: ed25519
      stored fpr .: 30541B420157F83AB50C1D7F753DD3A9B8B020A8
      created ....: 2023-11-25 14:01:02
Encryption key....: 71557B88E8EFA40D9B42D754AA131B9A213B5ACE
      keyref .....: OPENPGP.2  (encr)
      algorithm ..: cv25519
      stored fpr .: 86F038E093ECD060C6FA90760AE68AFC59ED5A30
      created ....: 2023-11-25 14:01:30
Authentication key: 96888FABE6E9BC75480D6E792AD10FC63D83C2FC
      keyref .....: OPENPGP.3  (sign,auth)
      algorithm ..: rsa2048
      stored fpr .: 82B309B19C4F096E96609BD6510A76CB6CF75B59
      created ....: 2023-11-25 13:52:44
gpg/card> q

Note above changes the login data to Doug but their command did not refresh the data.
Running again:

Reader ...........: Nitrokey Nitrokey Start (FSIJ-1.2.15-43123355) 00 00
Card type ........: gnuk
Serial number ....: D276000124010200FFFE001233550000
Application type .: OpenPGP
Version ..........: 2.0
Displayed s/n ....: FFFE 00123355
Manufacturer .....: unmanaged S/N range (fffe)
Name of cardholder: Doug (Nitro Start) Engert
Language prefs ...: [not set]
Salutation .......: 
URL of public key : [not set]
Login data .......: Doug
Signature PIN ....: forced
Max. PIN lengths .: 127 127 127
PIN retry counter : 3 3 3
...

Now it does show the login "Doug".

@dengert
Copy link
Member

dengert commented Feb 9, 2024

Here is a possible solution. update the card, close all sessions then call from your pkcs11 application:
rv = p11->C_InitToken(slot, NULL, 0, "REFRESH"); This will simulate a card removal and card insertion.

There are two slot listed for openpgp, one for each pin so it may call the code twice.

I tested if from pkcs11-tools as listed below, not the best place to do it.

Use at your own risk.

diff --git a/src/pkcs11/framework-pkcs15.c b/src/pkcs11/framework-pkcs15.c
index 9e71a9a22..3a55ab704 100644
--- a/src/pkcs11/framework-pkcs15.c
+++ b/src/pkcs11/framework-pkcs15.c
@@ -2070,6 +2070,8 @@ pkcs15_initialize(struct sc_pkcs11_slot *slot, void *ptr,
 	int rc, enable_InitToken = 0;
 	CK_RV rv;
 
+	if (strncmp(pLabel, "REFRESH", strlen("REFRESH")) != 0) {
+
 	sc_log(context, "Get 'enable-InitToken' card configuration option");
 	if (!p11card)
 		return CKR_TOKEN_NOT_RECOGNIZED;
@@ -2172,6 +2174,8 @@ pkcs15_initialize(struct sc_pkcs11_slot *slot, void *ptr,
 		return sc_to_cryptoki_error(rc, "C_InitToken");
 	}
 
+	} /* end of refresh */
+
 	rv = card_removed(p11card->reader);
 	if (rv != CKR_OK)   {
 		sc_log(context, "remove card error 0x%lX", rv);
diff --git a/src/tools/pkcs11-tool.c b/src/tools/pkcs11-tool.c
index 8561f71ab..1ffad48e3 100644
--- a/src/tools/pkcs11-tool.c
+++ b/src/tools/pkcs11-tool.c
@@ -1692,6 +1692,9 @@ static void show_token(CK_SLOT_ID slot)
 	printf("  serial num         : %s\n", p11_utf8_to_local(info.serialNumber,
 			sizeof(info.serialNumber)));
 	printf("  pin min/max        : %lu/%lu\n", info.ulMinPinLen, info.ulMaxPinLen);
+
+/* TEST */
+	rv = p11->C_InitToken(slot, NULL, 0, "REFRESH");
 }
 
 static void list_mechs(CK_SLOT_ID slot)

@frankmorgner
Copy link
Member

pgp_erase_card() uses TERMINATE DF and ACTIVATE FILE to delete the card's contents. However, this doesn't clean up the card driver's internal caching of the card's data (priv->pgp_objects). I think this causes the confusion at runtime.

This will be re-initialized along with the card handles when C_Finalize + C_Initialized are called. Note that creating and deleting a session does not cause re-initialization of the internal handles.

If you want to improve OpenSC, you may want to fix the state-keeping in card-openpgp.c around the internal pgp_blobs. If you want a quick solution, simply call C_Initialize after erasing the card (either through C_InitToken or via openpgp-tool).

@dengert
Copy link
Member

dengert commented Feb 12, 2024

@frank, you are right, the card drivers should do this, there maybe other card drivers that have the same problem. The quick solution for most people is to just remove the token and reinsert. @arrowd is not looking for a quick solution, with his daemon process.

But PKCS11 does not define a way to simulate removal and insertion. OpenSC's C_InitToken does simulate removal and insertion as the last steps in pkcs15_initialize

I said about the above patch "Use at your own risk." (which should not be in OpenSC) because if one was to call C_InitToken(slot, NULL, 0, "REFRESH"); with any other pkcs11 module that module would try to initialize the token with the label "REFRESH". It was meant as a one off mode for @arrowd.

As best I can tell @arrowd is trying to use opensc-explorer or call other sc_pkcs15 routines, (bypassing the PKCS11 layer) to update the '5E' blob.

OpenSC's OpenPGP pkcs15 or pkcs11 code does not have a way to update many of the "DOs" i.e. blobs defined by OpenPGP.
I can count at least 8: 101, 102, 103, 104, Name(5B) Login data (5E), Language preference (5F2D), Sex (5F35) most which require the the PW3 pin (i.e. PKCS11 CKU_SO) to update.

Whatever is done, looks like a lot of work, with little reward. It is not clear to me if using the "Login data (5E)" is even a good idea. Maybe using certificates issued by a good PKI infrastructure could be used to map to local login names as done with most other tokens.

@arrowd
Copy link
Author

arrowd commented Feb 12, 2024

Thanks everyone for your input. For now I settled with the following hack:

  1. Call card_removed(sc_slot->reader).
  2. Call sc_slot->reader->ops->cancel(sc_slot->reader->ctx).

The former call is possible because I put it into the library's export list. I probably should use some better entry point instead of that.
The latter call causes the thread waiting on C_WaitForSlotEvent() to return (with CKR_GENERAL_ERROR, but I'm ready for that). Calling C_WaitForSlotEvent() again reinitializes the whole sc_pkcs11_slot structure including pgp_* bits.

I will use this hack for now as I need to proceed with my daemon.

As best I can tell @arrowd is trying to use opensc-explorer or call other sc_pkcs15 routines, (bypassing the PKCS11 layer) to update the '5E' blob.

Like I said in #3018 (comment) , the problem can also be observed when using only PKCS11 API. From my (uneducated) POV the core issue is that libopensc caches a lot of stuff without having a proper way to reset the cache. If you agree on that and give me an idea on how to properly fix it within OpenSC, I will try to find spare time to do that. Otherwise I'll just stick to my hack.

Thanks again, the whole thread was quite helpful.

@frankmorgner
Copy link
Member

I tried to describe the faulty cache above (#3018 (comment)). I think a fix could be quite simple... please try #3024

frankmorgner added a commit to frankmorgner/OpenSC that referenced this issue Feb 27, 2024
@frankmorgner
Copy link
Member

@arrowd, could you please provide a debug log when running the two subsequent calls to C_GenerateKeyPair?

@arrowd
Copy link
Author

arrowd commented Mar 6, 2024

I started with inserting a token with a key pair already generated. The scenario is following:

  1. Get the public key, print it.
  2. Generate a new key pair.
  3. Get the public key, print it. It the same as before.
  4. Reinsert the token or restart my program.
  5. Get the public key, print it. Now it is different.

Here are the logs:

Act I: Getting the public key
P:77260; T:0x34403852288 20:50:30.926 [opensc-pkcs11] card.c:471:sc_lock: called
P:77260; T:0x34403852288 20:50:30.926 [opensc-pkcs11] reader-pcsc.c:690:pcsc_lock: called
P:77260; T:0x34403852288 20:50:30.926 [opensc-pkcs11] card-openpgp.c:3745:pgp_card_reader_lock_obtained: called
P:77260; T:0x34403852288 20:50:30.926 [opensc-pkcs11] card-openpgp.c:3772:pgp_card_reader_lock_obtained: returning with: 0 (Success)
P:77260; T:0x34403852288 20:50:30.926 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:77260; T:0x34403852288 20:50:30.926 [opensc-pkcs11] pkcs11-object.c:377:C_FindObjectsInit: C_FindObjectsInit(slot = 0)
P:77260; T:0x34403852288 20:50:30.926 [opensc-pkcs11] pkcs11-object.c:378:C_FindObjectsInit: C_FindObjectsInit(): CKA_ENCRYPT = TRUE
P:77260; T:0x34403852288 20:50:30.926 [opensc-pkcs11] misc.c:267:session_start_operation: called
P:77260; T:0x34403852288 20:50:30.926 [opensc-pkcs11] misc.c:268:session_start_operation: Session 0x806011150, type 0
P:77260; T:0x34403852288 20:50:30.926 [opensc-pkcs11] pkcs11-object.c:400:C_FindObjectsInit: Object with handle 0x805c0b240
P:77260; T:0x34403852288 20:50:30.926 [opensc-pkcs11] framework-pkcs15.c:4000:pkcs15_prkey_get_attribute: pkcs15_prkey_get_attribute() called
P:77260; T:0x34403852288 20:50:30.926 [opensc-pkcs11] pkcs11-object.c:409:C_FindObjectsInit: Object 0/34456252992: Private object and not logged in.
P:77260; T:0x34403852288 20:50:30.926 [opensc-pkcs11] pkcs11-object.c:400:C_FindObjectsInit: Object with handle 0x805c0b1e0
P:77260; T:0x34403852288 20:50:30.926 [opensc-pkcs11] framework-pkcs15.c:4891:pkcs15_pubkey_get_attribute: pkcs15_pubkey_get_attribute() called
P:77260; T:0x34403852288 20:50:30.926 [opensc-pkcs11] framework-pkcs15.c:4891:pkcs15_pubkey_get_attribute: pkcs15_pubkey_get_attribute() called
P:77260; T:0x34403852288 20:50:30.926 [opensc-pkcs11] framework-pkcs15.c:4891:pkcs15_pubkey_get_attribute: pkcs15_pubkey_get_attribute() called
P:77260; T:0x34403852288 20:50:30.926 [opensc-pkcs11] pkcs11-object.c:435:C_FindObjectsInit: Object 0/34456252896 matches
P:77260; T:0x34403852288 20:50:30.926 [opensc-pkcs11] pkcs11-object.c:439:C_FindObjectsInit: realloc for 32 handles
P:77260; T:0x34403852288 20:50:30.926 [opensc-pkcs11] pkcs11-object.c:400:C_FindObjectsInit: Object with handle 0x805c23050
P:77260; T:0x34403852288 20:50:30.927 [opensc-pkcs11] framework-pkcs15.c:5328:pkcs15_profile_get_attribute: pkcs15_profile_get_attribute() called
P:77260; T:0x34403852288 20:50:30.927 [opensc-pkcs11] framework-pkcs15.c:5328:pkcs15_profile_get_attribute: pkcs15_profile_get_attribute() called
P:77260; T:0x34403852288 20:50:30.927 [opensc-pkcs11] pkcs11-object.c:421:C_FindObjectsInit: Object 0/34456350800: Attribute 0x104 does NOT match.
P:77260; T:0x34403852288 20:50:30.927 [opensc-pkcs11] pkcs11-object.c:452:C_FindObjectsInit: 1 matching objects
P:77260; T:0x34403852288 20:50:30.927 [opensc-pkcs11] misc.c:289:session_get_operation: called
P:77260; T:0x34403852288 20:50:30.927 [opensc-pkcs11] misc.c:289:session_get_operation: called
P:77260; T:0x34403852288 20:50:30.927 [opensc-pkcs11] framework-pkcs15.c:4891:pkcs15_pubkey_get_attribute: pkcs15_pubkey_get_attribute() called
P:77260; T:0x34403852288 20:50:30.927 [opensc-pkcs11] pkcs11-object.c:270:C_GetAttributeValue: Object 34456252896: CKA_MODULUS = <size inquiry>
P:77260; T:0x34403852288 20:50:30.927 [opensc-pkcs11] pkcs11-object.c:295:C_GetAttributeValue: C_GetAttributeValue(hSession=0x806011150, hObject=0x805c0b1e0) = CKR_OK
P:77260; T:0x34403852288 20:50:30.927 [opensc-pkcs11] framework-pkcs15.c:4891:pkcs15_pubkey_get_attribute: pkcs15_pubkey_get_attribute() called
P:77260; T:0x34403852288 20:50:30.927 [opensc-pkcs11] pkcs11-object.c:270:C_GetAttributeValue: Object 34456252896: CKA_MODULUS = D771D9DE31F225C15891D08ADA2B5BBBB024E7D2345140A552DA12B3FFECE34B
P:77260; T:0x34403852288 20:50:30.927 [opensc-pkcs11] pkcs11-object.c:295:C_GetAttributeValue: C_GetAttributeValue(hSession=0x806011150, hObject=0x805c0b1e0) = CKR_OK
P:77260; T:0x34403852288 20:50:30.927 [opensc-pkcs11] framework-pkcs15.c:4891:pkcs15_pubkey_get_attribute: pkcs15_pubkey_get_attribute() called
P:77260; T:0x34403852288 20:50:30.927 [opensc-pkcs11] pkcs11-object.c:270:C_GetAttributeValue: Object 34456252896: CKA_PUBLIC_EXPONENT = <size inquiry>
P:77260; T:0x34403852288 20:50:30.927 [opensc-pkcs11] pkcs11-object.c:295:C_GetAttributeValue: C_GetAttributeValue(hSession=0x806011150, hObject=0x805c0b1e0) = CKR_OK
P:77260; T:0x34403852288 20:50:30.927 [opensc-pkcs11] framework-pkcs15.c:4891:pkcs15_pubkey_get_attribute: pkcs15_pubkey_get_attribute() called
P:77260; T:0x34403852288 20:50:30.927 [opensc-pkcs11] pkcs11-object.c:270:C_GetAttributeValue: Object 34456252896: CKA_PUBLIC_EXPONENT = 010001
P:77260; T:0x34403852288 20:50:30.927 [opensc-pkcs11] pkcs11-object.c:295:C_GetAttributeValue: C_GetAttributeValue(hSession=0x806011150, hObject=0x805c0b1e0) = CKR_OK
P:77260; T:0x34403852288 20:50:30.927 [opensc-pkcs11] card.c:523:sc_unlock: called
P:77260; T:0x34403852288 20:50:30.927 [opensc-pkcs11] reader-pcsc.c:742:pcsc_unlock: called
Act II: Logging in as SO
P:77260; T:0x34403864832 20:51:22.852 [opensc-pkcs11] card.c:471:sc_lock: called
P:77260; T:0x34403864832 20:51:22.852 [opensc-pkcs11] reader-pcsc.c:690:pcsc_lock: called
P:77260; T:0x34403864832 20:51:22.852 [opensc-pkcs11] card-openpgp.c:3745:pgp_card_reader_lock_obtained: called
P:77260; T:0x34403864832 20:51:22.852 [opensc-pkcs11] card-openpgp.c:3772:pgp_card_reader_lock_obtained: returning with: 0 (Success)
P:77260; T:0x34403864832 20:51:22.852 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:77260; T:0x34403864832 20:51:22.852 [opensc-pkcs11] pkcs11-session.c:352:C_Login: C_Login(0x806011150, 0)
P:77260; T:0x34403864832 20:51:22.852 [opensc-pkcs11] pkcs11-session.c:374:C_Login: C_Login() slot->login_user -1
P:77260; T:0x34403864832 20:51:22.852 [opensc-pkcs11] pkcs11-session.c:385:C_Login: C_Login() userType 0
P:77260; T:0x34403864832 20:51:22.852 [opensc-pkcs11] framework-pkcs15.c:1778:pkcs15_login: pkcs15-login: userType 0x0, PIN length 9
P:77260; T:0x34403864832 20:51:22.852 [opensc-pkcs11] framework-pkcs15.c:1789:pkcs15_login: pkcs15-login: find SO PIN: rc 0
P:77260; T:0x34403864832 20:51:22.852 [opensc-pkcs11] pkcs15-pin.c:304:sc_pkcs15_verify_pin: called
P:77260; T:0x34403864832 20:51:22.852 [opensc-pkcs11] pkcs15-pin.c:351:sc_pkcs15_verify_pin_with_session_pin: called
P:77260; T:0x34403864832 20:51:22.852 [opensc-pkcs11] pkcs15-pin.c:355:sc_pkcs15_verify_pin_with_session_pin: PIN(type:0; method:1; value(0x806018098:9)
P:77260; T:0x34403864832 20:51:22.852 [opensc-pkcs11] card.c:471:sc_lock: called
P:77260; T:0x34403864832 20:51:22.852 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:77260; T:0x34403864832 20:51:22.853 [opensc-pkcs11] card.c:850:sc_select_file: called; type=2, path=3f00
P:77260; T:0x34403864832 20:51:22.853 [opensc-pkcs11] card-openpgp.c:1456:pgp_select_file: called
P:77260; T:0x34403864832 20:51:22.853 [opensc-pkcs11] card-openpgp.c:1520:pgp_select_file: returning with: 0 (Success)
P:77260; T:0x34403864832 20:51:22.853 [opensc-pkcs11] card.c:885:sc_select_file: returning with: 0 (Success)
P:77260; T:0x34403864832 20:51:22.853 [opensc-pkcs11] sec.c:203:sc_pin_cmd: called
P:77260; T:0x34403864832 20:51:23.490 [opensc-pkcs11] sec.c:259:sc_pin_cmd: returning with: 0 (Success)
P:77260; T:0x34403864832 20:51:23.490 [opensc-pkcs11] pkcs15-pin.c:443:sc_pkcs15_verify_pin_with_session_pin: PIN cmd result 0
P:77260; T:0x34403864832 20:51:23.490 [opensc-pkcs11] pkcs15-pin.c:749:sc_pkcs15_pincache_add: called
P:77260; T:0x34403864832 20:51:23.490 [opensc-pkcs11] pkcs15-pin.c:793:sc_pkcs15_pincache_add: PIN(Admin PIN) cached
P:77260; T:0x34403864832 20:51:23.490 [opensc-pkcs11] card.c:523:sc_unlock: called
P:77260; T:0x34403864832 20:51:23.490 [opensc-pkcs11] pkcs15-pin.c:465:sc_pkcs15_verify_pin_with_session_pin: returning with: 0 (Success)
P:77260; T:0x34403864832 20:51:23.490 [opensc-pkcs11] pkcs15-pin.c:749:sc_pkcs15_pincache_add: called
P:77260; T:0x34403864832 20:51:23.491 [opensc-pkcs11] pkcs15-pin.c:793:sc_pkcs15_pincache_add: PIN(Admin PIN) cached
P:77260; T:0x34403864832 20:51:23.491 [opensc-pkcs11] pkcs15-pin.c:321:sc_pkcs15_verify_pin: returning with: 0 (Success)
P:77260; T:0x34403864832 20:51:23.491 [opensc-pkcs11] framework-pkcs15.c:1881:pkcs15_login: PKCS15 verify PIN returned 0
P:77260; T:0x34403864832 20:51:23.491 [opensc-pkcs11] pkcs11-session.c:389:C_Login: fLogin() rv 0
P:77260; T:0x34403864832 20:51:23.491 [opensc-pkcs11] card.c:523:sc_unlock: called
P:77260; T:0x34403864832 20:51:23.491 [opensc-pkcs11] reader-pcsc.c:742:pcsc_unlock: called
Act III: Generating a new pair
P:77260; T:0x34403866624 20:51:54.181 [opensc-pkcs11] card.c:471:sc_lock: called
P:77260; T:0x34403866624 20:51:54.181 [opensc-pkcs11] reader-pcsc.c:690:pcsc_lock: called
P:77260; T:0x34403866624 20:51:54.182 [opensc-pkcs11] card-openpgp.c:3745:pgp_card_reader_lock_obtained: called
P:77260; T:0x34403866624 20:51:54.182 [opensc-pkcs11] card-openpgp.c:3772:pgp_card_reader_lock_obtained: returning with: 0 (Success)
P:77260; T:0x34403866624 20:51:54.182 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:77260; T:0x34403866624 20:51:54.182 [opensc-pkcs11] pkcs11-object.c:1161:C_GenerateKeyPair: C_GenerateKeyPair(), PrivKey attrs: CKA_CLASS = CKO_PRIVATE_KEY
P:77260; T:0x34403866624 20:51:54.182 [opensc-pkcs11] pkcs11-object.c:1161:C_GenerateKeyPair: C_GenerateKeyPair(), PrivKey attrs: CKA_TOKEN = TRUE
P:77260; T:0x34403866624 20:51:54.182 [opensc-pkcs11] pkcs11-object.c:1161:C_GenerateKeyPair: C_GenerateKeyPair(), PrivKey attrs: CKA_PRIVATE = TRUE
P:77260; T:0x34403866624 20:51:54.182 [opensc-pkcs11] pkcs11-object.c:1161:C_GenerateKeyPair: C_GenerateKeyPair(), PrivKey attrs: CKA_SENSITIVE = TRUE
P:77260; T:0x34403866624 20:51:54.182 [opensc-pkcs11] pkcs11-object.c:1162:C_GenerateKeyPair: C_GenerateKeyPair(), PubKey attrs: CKA_CLASS = CKO_PUBLIC_KEY
P:77260; T:0x34403866624 20:51:54.182 [opensc-pkcs11] pkcs11-object.c:1162:C_GenerateKeyPair: C_GenerateKeyPair(), PubKey attrs: CKA_TOKEN = TRUE
P:77260; T:0x34403866624 20:51:54.182 [opensc-pkcs11] pkcs11-object.c:1162:C_GenerateKeyPair: C_GenerateKeyPair(), PubKey attrs: CKA_PRIVATE = FALSE
P:77260; T:0x34403866624 20:51:54.182 [opensc-pkcs11] pkcs11-object.c:1162:C_GenerateKeyPair: C_GenerateKeyPair(), PubKey attrs: CKA_MODULUS_BITS = 0x800
P:77260; T:0x34403866624 20:51:54.182 [opensc-pkcs11] framework-pkcs15.c:3282:pkcs15_gen_keypair: Key pair generation, mech = 0x0
P:77260; T:0x34403866624 20:51:54.182 [opensc-pkcs11] card.c:471:sc_lock: called
P:77260; T:0x34403866624 20:51:54.182 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:77260; T:0x34403866624 20:51:54.182 [opensc-pkcs11] pkcs15-lib.c:321:sc_pkcs15init_bind: called
P:77260; T:0x34403866624 20:51:54.182 [opensc-pkcs11] card.c:1119:sc_card_ctl: called
P:77260; T:0x34403866624 20:51:54.182 [opensc-pkcs11] card-openpgp.c:3584:pgp_card_ctl: called
P:77260; T:0x34403866624 20:51:54.183 [opensc-pkcs11] card-openpgp.c:3611:pgp_card_ctl: returning with: -1408 (Not supported)
P:77260; T:0x34403866624 20:51:54.183 [opensc-pkcs11] card.c:1126:sc_card_ctl: card_ctl(4) not supported
P:77260; T:0x34403866624 20:51:54.183 [opensc-pkcs11] card.c:850:sc_select_file: called; type=2, path=3f0050154946
P:77260; T:0x34403866624 20:51:54.183 [opensc-pkcs11] card-openpgp.c:1456:pgp_select_file: called
P:77260; T:0x34403866624 20:51:54.183 [opensc-pkcs11] card-openpgp.c:1510:pgp_select_file: returning with: -1201 (File not found)
P:77260; T:0x34403866624 20:51:54.183 [opensc-pkcs11] card.c:872:sc_select_file: 'SELECT' error: -1201 (File not found)
P:77260; T:0x34403866624 20:51:54.183 [opensc-pkcs11] profile.c:337:sc_profile_load: called
P:77260; T:0x34403866624 20:51:54.183 [opensc-pkcs11] profile.c:357:sc_profile_load: Using profile directory '/usr/local/share/opensc'.
P:77260; T:0x34403866624 20:51:54.183 [opensc-pkcs11] profile.c:365:sc_profile_load: Trying profile file /usr/local/share/opensc/pkcs15.profile
P:77260; T:0x34403866624 20:51:54.185 [opensc-pkcs11] profile.c:370:sc_profile_load: profile /usr/local/share/opensc/pkcs15.profile loaded ok
P:77260; T:0x34403866624 20:51:54.185 [opensc-pkcs11] profile.c:384:sc_profile_load: returning with: 0 (Success)
P:77260; T:0x34403866624 20:51:54.185 [opensc-pkcs11] profile.c:337:sc_profile_load: called
P:77260; T:0x34403866624 20:51:54.185 [opensc-pkcs11] profile.c:357:sc_profile_load: Using profile directory '/usr/local/share/opensc'.
P:77260; T:0x34403866624 20:51:54.185 [opensc-pkcs11] profile.c:365:sc_profile_load: Trying profile file /usr/local/share/opensc/openpgp.profile
P:77260; T:0x34403866624 20:51:54.186 [opensc-pkcs11] profile.c:370:sc_profile_load: profile /usr/local/share/opensc/openpgp.profile loaded ok
P:77260; T:0x34403866624 20:51:54.186 [opensc-pkcs11] profile.c:384:sc_profile_load: returning with: 0 (Success)
P:77260; T:0x34403866624 20:51:54.186 [opensc-pkcs11] profile.c:396:sc_profile_finish: called
P:77260; T:0x34403866624 20:51:54.187 [opensc-pkcs11] profile.c:439:sc_profile_finish: returning with: 0 (Success)
P:77260; T:0x34403866624 20:51:54.187 [opensc-pkcs11] pkcs15-lib.c:428:sc_pkcs15init_bind: returning with: 0 (Success)
P:77260; T:0x34403866624 20:51:54.187 [opensc-pkcs11] pkcs15-lib.c:761:sc_pkcs15init_finalize_profile: called
P:77260; T:0x34403866624 20:51:54.187 [opensc-pkcs11] pkcs15-lib.c:776:sc_pkcs15init_finalize_profile: Finalize profile with application 'default'
P:77260; T:0x34403866624 20:51:54.187 [opensc-pkcs11] profile.c:396:sc_profile_finish: called
P:77260; T:0x34403866624 20:51:54.187 [opensc-pkcs11] profile.c:439:sc_profile_finish: returning with: 0 (Success)
P:77260; T:0x34403866624 20:51:54.187 [opensc-pkcs11] pkcs15-lib.c:779:sc_pkcs15init_finalize_profile: sc_pkcs15init_finalize_profile() returns 0
P:77260; T:0x34403866624 20:51:54.187 [opensc-pkcs11] pkcs15-lib.c:780:sc_pkcs15init_finalize_profile: returning with: 0 (Success)
P:77260; T:0x34403866624 20:51:54.187 [opensc-pkcs11] pkcs15-lib.c:458:sc_pkcs15init_set_p15card: called
P:77260; T:0x34403866624 20:51:54.187 [opensc-pkcs11] profile.c:633:sc_profile_get_file_by_path: called
P:77260; T:0x34403866624 20:51:54.187 [opensc-pkcs11] profile.c:637:sc_profile_get_file_by_path: returning with: 0 (Success)
P:77260; T:0x34403866624 20:51:54.187 [opensc-pkcs11] profile.c:633:sc_profile_get_file_by_path: called
P:77260; T:0x34403866624 20:51:54.187 [opensc-pkcs11] profile.c:637:sc_profile_get_file_by_path: returning with: 0 (Success)
P:77260; T:0x34403866624 20:51:54.187 [opensc-pkcs11] pkcs15-lib.c:491:sc_pkcs15init_set_p15card: sc_pkcs15init_set_p15card() returns
P:77260; T:0x34403866624 20:51:54.187 [opensc-pkcs11] framework-pkcs15.c:3453:pkcs15_gen_keypair: Try on-card key pair generation
P:77260; T:0x34403866624 20:51:54.187 [opensc-pkcs11] pkcs15-lib.c:1547:sc_pkcs15init_generate_key: called
P:77260; T:0x34403866624 20:51:54.187 [opensc-pkcs11] pkcs15-lib.c:2538:check_keygen_params_consistency: returning with: 0 (Success)
P:77260; T:0x34403866624 20:51:54.187 [opensc-pkcs11] pkcs15-lib.c:2561:check_key_compatibility: called
P:77260; T:0x34403866624 20:51:54.187 [opensc-pkcs11] pkcs15-lib.c:2595:check_key_compatibility: returning with: 0 (Success)
P:77260; T:0x34403866624 20:51:54.187 [opensc-pkcs11] pkcs15-lib.c:1244:sc_pkcs15init_init_prkdf: called
P:77260; T:0x34403866624 20:51:54.187 [opensc-pkcs11] pkcs15-lib.c:2902:select_id: called
P:77260; T:0x34403866624 20:51:54.187 [opensc-pkcs11] pkcs15-lib.c:2947:select_id: returning with: 0 (Success)
P:77260; T:0x34403866624 20:51:54.188 [opensc-pkcs11] pkcs15-lib.c:3034:select_object_path: called
P:77260; T:0x34403866624 20:51:54.188 [opensc-pkcs11] pkcs15-lib.c:3059:select_object_path: key-domain.private-key @3f005015 (auth_id.len=1)
P:77260; T:0x34403866624 20:51:54.188 [opensc-pkcs11] profile.c:707:sc_profile_instantiate_template: Instantiating template key-domain at 3f005015
P:77260; T:0x34403866624 20:51:54.188 [opensc-pkcs11] profile.c:790:sc_profile_instantiate_file: Instantiated private-key at 3f0050155f48
P:77260; T:0x34403866624 20:51:54.188 [opensc-pkcs11] profile.c:791:sc_profile_instantiate_file:   parent=PKCS15-AppDF@3f005015
P:77260; T:0x34403866624 20:51:54.188 [opensc-pkcs11] pkcs15-lib.c:3081:select_object_path: instantiated template path 3f0050155f48
P:77260; T:0x34403866624 20:51:54.188 [opensc-pkcs11] pkcs15-lib.c:3110:select_object_path: returns object path '3f0050155f48'
P:77260; T:0x34403866624 20:51:54.188 [opensc-pkcs11] pkcs15-lib.c:3111:select_object_path: returning with: 0 (Success)
P:77260; T:0x34403866624 20:51:54.188 [opensc-pkcs11] pkcs15-lib.c:1373:sc_pkcs15init_init_prkdf: returning with: 0 (Success)
P:77260; T:0x34403866624 20:51:54.188 [opensc-pkcs11] pkcs15-lib.c:1484:_pkcd15init_set_aux_md_data: called
P:77260; T:0x34403866624 20:51:54.188 [opensc-pkcs11] pkcs15-lib.c:1487:_pkcd15init_set_aux_md_data: returning with: 0 (Success)
P:77260; T:0x34403866624 20:51:54.188 [opensc-pkcs11] pkcs15-openpgp.c:103:openpgp_create_key: called
P:77260; T:0x34403866624 20:51:54.188 [opensc-pkcs11] pkcs15-openpgp.c:104:openpgp_create_key: returning with: 0 (Success)
P:77260; T:0x34403866624 20:51:54.188 [opensc-pkcs11] pkcs15-openpgp.c:373:openpgp_generate_key: called
P:77260; T:0x34403866624 20:51:54.188 [opensc-pkcs11] pkcs15-openpgp.c:209:openpgp_generate_key_rsa: called
P:77260; T:0x34403866624 20:51:54.188 [opensc-pkcs11] pkcs15-openpgp.c:211:openpgp_generate_key_rsa: Key ID to be generated: 45
P:77260; T:0x34403866624 20:51:54.188 [opensc-pkcs11] pkcs15-openpgp.c:217:openpgp_generate_key_rsa: Authentication key is to be generated.
P:77260; T:0x34403866624 20:51:54.188 [opensc-pkcs11] card.c:1119:sc_card_ctl: called
P:77260; T:0x34403866624 20:51:54.188 [opensc-pkcs11] card-openpgp.c:3584:pgp_card_ctl: called
P:77260; T:0x34403866624 20:51:54.188 [opensc-pkcs11] card-openpgp.c:3020:pgp_gen_key: called
P:77260; T:0x34403866624 20:51:54.188 [opensc-pkcs11] card-openpgp.c:2509:pgp_update_new_algo_attr: called
P:77260; T:0x34403866624 20:51:54.188 [opensc-pkcs11] card-openpgp.c:1986:pgp_put_data: called
P:77260; T:0x34403866624 20:51:54.188 [opensc-pkcs11] card-openpgp.c:1938:pgp_put_data_plain: called
P:77260; T:0x34403866624 20:51:54.189 [opensc-pkcs11] apdu.c:550:sc_transmit_apdu: called
P:77260; T:0x34403866624 20:51:54.189 [opensc-pkcs11] card.c:471:sc_lock: called
P:77260; T:0x34403866624 20:51:54.189 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:77260; T:0x34403866624 20:51:54.189 [opensc-pkcs11] apdu.c:515:sc_transmit: called
P:77260; T:0x34403866624 20:51:54.189 [opensc-pkcs11] apdu.c:363:sc_single_transmit: called
P:77260; T:0x34403866624 20:51:54.189 [opensc-pkcs11] apdu.c:370:sc_single_transmit: CLA:0, INS:DA, P1:0, P2:C3, data(6) 0x8060092c8
P:77260; T:0x34403866624 20:51:54.189 [opensc-pkcs11] reader-pcsc.c:325:pcsc_transmit: reader 'Nitrokey Nitrokey 3 [CCID/ICCD Interface] 00 00'
P:77260; T:0x34403866624 20:51:54.189 [opensc-pkcs11] reader-pcsc.c:326:pcsc_transmit: 
Outgoing APDU (11 bytes):
00 DA 00 C3 06 01 08 00 00 20 00 ......... .

P:77260; T:0x34403866624 20:51:54.189 [opensc-pkcs11] reader-pcsc.c:244:pcsc_internal_transmit: called
P:77260; T:0x34403866624 20:51:54.280 [opensc-pkcs11] reader-pcsc.c:335:pcsc_transmit: 
Incoming APDU (2 bytes):
90 00 ..

P:77260; T:0x34403866624 20:51:54.280 [opensc-pkcs11] apdu.c:382:sc_single_transmit: returning with: 0 (Success)
P:77260; T:0x34403866624 20:51:54.280 [opensc-pkcs11] apdu.c:539:sc_transmit: returning with: 0 (Success)
P:77260; T:0x34403866624 20:51:54.280 [opensc-pkcs11] card.c:523:sc_unlock: called
P:77260; T:0x34403866624 20:51:54.280 [opensc-pkcs11] card-openpgp.c:1971:pgp_put_data_plain: returning with: 6
P:77260; T:0x34403866624 20:51:54.280 [opensc-pkcs11] card-openpgp.c:2035:pgp_put_data: Updating the corresponding blob data
P:77260; T:0x34403866624 20:51:54.281 [opensc-pkcs11] card-openpgp.c:2042:pgp_put_data: returning with: 6
P:77260; T:0x34403866624 20:51:54.281 [opensc-pkcs11] card-openpgp.c:2572:pgp_update_new_algo_attr: returning with: 6
P:77260; T:0x34403866624 20:51:54.281 [opensc-pkcs11] card-openpgp.c:3081:pgp_gen_key: Waiting for the card to generate key...
P:77260; T:0x34403866624 20:51:54.281 [opensc-pkcs11] apdu.c:550:sc_transmit_apdu: called
P:77260; T:0x34403866624 20:51:54.281 [opensc-pkcs11] card.c:471:sc_lock: called
P:77260; T:0x34403866624 20:51:54.281 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:77260; T:0x34403866624 20:51:54.281 [opensc-pkcs11] apdu.c:515:sc_transmit: called
P:77260; T:0x34403866624 20:51:54.281 [opensc-pkcs11] apdu.c:363:sc_single_transmit: called
P:77260; T:0x34403866624 20:51:54.281 [opensc-pkcs11] apdu.c:370:sc_single_transmit: CLA:0, INS:47, P1:80, P2:0, data(2) 0x7fffdf3f6026
P:77260; T:0x34403866624 20:51:54.281 [opensc-pkcs11] reader-pcsc.c:325:pcsc_transmit: reader 'Nitrokey Nitrokey 3 [CCID/ICCD Interface] 00 00'
P:77260; T:0x34403866624 20:51:54.281 [opensc-pkcs11] reader-pcsc.c:326:pcsc_transmit: 
Outgoing APDU (11 bytes):
00 47 80 00 00 00 02 A4 00 1D B9 .G.........

P:77260; T:0x34403866624 20:51:54.281 [opensc-pkcs11] reader-pcsc.c:244:pcsc_internal_transmit: called
P:77260; T:0x34403866624 20:54:44.749 [opensc-pkcs11] reader-pcsc.c:335:pcsc_transmit: 
Incoming APDU (272 bytes):
7F 49 82 01 09 81 82 01 00 CF E2 3D B6 56 37 F2 .I.........=.V7.
2C 50 02 84 1D 92 EA A1 81 CD 62 6D F4 41 85 37 ,P........bm.A.7
62 74 2F 06 C6 67 43 EF 2A 87 67 01 CC DF D9 2F bt/..gC.*.g..../
28 74 42 77 22 33 17 73 FD EC D8 07 21 E4 91 FE (tBw"3.s....!...
09 9B B1 7A 34 71 40 16 24 DC B7 AB 08 77 2E 4F ...z4q@.$....w.O
C8 01 70 EC 1E B0 76 5E 56 AF 8B 14 7D 25 86 8C ..p...v^V...}%..
8E 69 1D 52 98 EF D2 86 C2 65 59 86 07 33 CE 49 .i.R.....eY..3.I
A2 33 85 7A 84 BF 90 89 FF 83 98 4C AA 40 A6 8B .3.z.......L.@..
3E 5A 52 2E 1E 19 A9 04 46 E5 6F 7F A2 2D B3 A7 >ZR.....F.o..-..
D2 D0 87 98 5F 25 A0 4A 4C B3 E3 C3 55 B3 DC 6D ...._%.JL...U..m
84 13 30 D4 C5 07 7E 7F 23 E7 4A DB 25 3E 9A 27 ..0...~.#.J.%>.'
00 79 68 42 9E D3 B3 F6 B8 17 2C A3 30 D0 00 A2 .yhB......,.0...
9B 1D 77 E8 41 9D 9D EF 58 31 FD 6C F6 EC D5 CB ..w.A...X1.l....
63 76 CF C5 74 31 80 6C BC E2 F2 76 03 87 1F D9 cv..t1.l...v....
84 A7 F5 92 6B 12 FB 2A B7 4D E3 C4 6B D0 AD 14 ....k..*.M..k...
4F EF 3D D5 64 27 EE 9B 8E AB A4 8D 5E 60 C4 FD O.=.d'......^`..
F3 14 90 C5 A8 DC 25 23 2D 82 03 01 00 01 90 00 ......%#-.......

P:77260; T:0x34403866624 20:54:44.749 [opensc-pkcs11] apdu.c:382:sc_single_transmit: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:44.749 [opensc-pkcs11] apdu.c:539:sc_transmit: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:44.749 [opensc-pkcs11] card.c:523:sc_unlock: called
P:77260; T:0x34403866624 20:54:44.749 [opensc-pkcs11] card-openpgp.c:3083:pgp_gen_key: Card has done key generation.
P:77260; T:0x34403866624 20:54:44.750 [opensc-pkcs11] card-openpgp.c:2878:pgp_parse_and_set_pubkey_output: called
P:77260; T:0x34403866624 20:54:44.750 [opensc-pkcs11] card-openpgp.c:2592:pgp_store_creationtime: called
P:77260; T:0x34403866624 20:54:44.750 [opensc-pkcs11] card-openpgp.c:2612:pgp_store_creationtime: Creation time Wed Mar  6 17:54:44 2024 UTC.
P:77260; T:0x34403866624 20:54:44.750 [opensc-pkcs11] card-openpgp.c:1986:pgp_put_data: called
P:77260; T:0x34403866624 20:54:44.750 [opensc-pkcs11] card.c:893:sc_get_data: called, tag=007a
P:77260; T:0x34403866624 20:54:44.750 [opensc-pkcs11] card-openpgp.c:1835:pgp_get_data: called
P:77260; T:0x34403866624 20:54:44.750 [opensc-pkcs11] apdu.c:550:sc_transmit_apdu: called
P:77260; T:0x34403866624 20:54:44.750 [opensc-pkcs11] card.c:471:sc_lock: called
P:77260; T:0x34403866624 20:54:44.750 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:44.750 [opensc-pkcs11] apdu.c:515:sc_transmit: called
P:77260; T:0x34403866624 20:54:44.750 [opensc-pkcs11] apdu.c:363:sc_single_transmit: called
P:77260; T:0x34403866624 20:54:44.750 [opensc-pkcs11] apdu.c:370:sc_single_transmit: CLA:0, INS:CA, P1:0, P2:7A, data(0) 0x0
P:77260; T:0x34403866624 20:54:44.750 [opensc-pkcs11] reader-pcsc.c:325:pcsc_transmit: reader 'Nitrokey Nitrokey 3 [CCID/ICCD Interface] 00 00'
P:77260; T:0x34403866624 20:54:44.750 [opensc-pkcs11] reader-pcsc.c:326:pcsc_transmit: 
Outgoing APDU (7 bytes):
00 CA 00 7A 00 20 00 ...z. .

P:77260; T:0x34403866624 20:54:44.750 [opensc-pkcs11] reader-pcsc.c:244:pcsc_internal_transmit: called
P:77260; T:0x34403866624 20:54:44.803 [opensc-pkcs11] reader-pcsc.c:335:pcsc_transmit: 
Incoming APDU (7 bytes):
93 03 00 00 00 90 00 .......

P:77260; T:0x34403866624 20:54:44.804 [opensc-pkcs11] apdu.c:382:sc_single_transmit: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:44.804 [opensc-pkcs11] apdu.c:539:sc_transmit: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:44.804 [opensc-pkcs11] card.c:523:sc_unlock: called
P:77260; T:0x34403866624 20:54:44.804 [opensc-pkcs11] card-openpgp.c:1862:pgp_get_data: returning with: 5
P:77260; T:0x34403866624 20:54:44.804 [opensc-pkcs11] card.c:898:sc_get_data: returning with: 5
P:77260; T:0x34403866624 20:54:44.804 [opensc-pkcs11] card-openpgp.c:1632:pgp_get_pubkey: called, tag=b600
P:77260; T:0x34403866624 20:54:44.804 [opensc-pkcs11] apdu.c:550:sc_transmit_apdu: called
P:77260; T:0x34403866624 20:54:44.804 [opensc-pkcs11] card.c:471:sc_lock: called
P:77260; T:0x34403866624 20:54:44.804 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:44.804 [opensc-pkcs11] apdu.c:515:sc_transmit: called
P:77260; T:0x34403866624 20:54:44.804 [opensc-pkcs11] apdu.c:363:sc_single_transmit: called
P:77260; T:0x34403866624 20:54:44.804 [opensc-pkcs11] apdu.c:370:sc_single_transmit: CLA:0, INS:47, P1:81, P2:0, data(2) 0x7fffdf3f38b6
P:77260; T:0x34403866624 20:54:44.804 [opensc-pkcs11] reader-pcsc.c:325:pcsc_transmit: reader 'Nitrokey Nitrokey 3 [CCID/ICCD Interface] 00 00'
P:77260; T:0x34403866624 20:54:44.804 [opensc-pkcs11] reader-pcsc.c:326:pcsc_transmit: 
Outgoing APDU (11 bytes):
00 47 81 00 00 00 02 B6 00 20 00 .G....... .

P:77260; T:0x34403866624 20:54:44.804 [opensc-pkcs11] reader-pcsc.c:244:pcsc_internal_transmit: called
P:77260; T:0x34403866624 20:54:44.857 [opensc-pkcs11] reader-pcsc.c:335:pcsc_transmit: 
Incoming APDU (2 bytes):
6A 88 j.

P:77260; T:0x34403866624 20:54:44.857 [opensc-pkcs11] apdu.c:382:sc_single_transmit: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:44.857 [opensc-pkcs11] apdu.c:539:sc_transmit: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:44.857 [opensc-pkcs11] card.c:523:sc_unlock: called
P:77260; T:0x34403866624 20:54:44.857 [opensc-pkcs11] iso7816.c:128:iso7816_check_sw: Referenced data not found
P:77260; T:0x34403866624 20:54:44.857 [opensc-pkcs11] card-openpgp.c:1646:pgp_get_pubkey: Card returned error: -1216 (Data object not found)
P:77260; T:0x34403866624 20:54:44.857 [opensc-pkcs11] card-openpgp.c:1632:pgp_get_pubkey: called, tag=b800
P:77260; T:0x34403866624 20:54:44.857 [opensc-pkcs11] apdu.c:550:sc_transmit_apdu: called
P:77260; T:0x34403866624 20:54:44.857 [opensc-pkcs11] card.c:471:sc_lock: called
P:77260; T:0x34403866624 20:54:44.858 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:44.858 [opensc-pkcs11] apdu.c:515:sc_transmit: called
P:77260; T:0x34403866624 20:54:44.858 [opensc-pkcs11] apdu.c:363:sc_single_transmit: called
P:77260; T:0x34403866624 20:54:44.858 [opensc-pkcs11] apdu.c:370:sc_single_transmit: CLA:0, INS:47, P1:81, P2:0, data(2) 0x7fffdf3f38b6
P:77260; T:0x34403866624 20:54:44.858 [opensc-pkcs11] reader-pcsc.c:325:pcsc_transmit: reader 'Nitrokey Nitrokey 3 [CCID/ICCD Interface] 00 00'
P:77260; T:0x34403866624 20:54:44.858 [opensc-pkcs11] reader-pcsc.c:326:pcsc_transmit: 
Outgoing APDU (11 bytes):
00 47 81 00 00 00 02 B8 00 20 00 .G....... .

P:77260; T:0x34403866624 20:54:44.858 [opensc-pkcs11] reader-pcsc.c:244:pcsc_internal_transmit: called
P:77260; T:0x34403866624 20:54:44.911 [opensc-pkcs11] reader-pcsc.c:335:pcsc_transmit: 
Incoming APDU (2 bytes):
6A 88 j.

P:77260; T:0x34403866624 20:54:44.911 [opensc-pkcs11] apdu.c:382:sc_single_transmit: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:44.911 [opensc-pkcs11] apdu.c:539:sc_transmit: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:44.911 [opensc-pkcs11] card.c:523:sc_unlock: called
P:77260; T:0x34403866624 20:54:44.911 [opensc-pkcs11] iso7816.c:128:iso7816_check_sw: Referenced data not found
P:77260; T:0x34403866624 20:54:44.911 [opensc-pkcs11] card-openpgp.c:1646:pgp_get_pubkey: Card returned error: -1216 (Data object not found)
P:77260; T:0x34403866624 20:54:44.911 [opensc-pkcs11] card-openpgp.c:1399:pgp_find_blob: Failed to seek the blob representing the tag 00D0. Error -1201.
P:77260; T:0x34403866624 20:54:44.911 [opensc-pkcs11] card-openpgp.c:1938:pgp_put_data_plain: called
P:77260; T:0x34403866624 20:54:44.911 [opensc-pkcs11] apdu.c:550:sc_transmit_apdu: called
P:77260; T:0x34403866624 20:54:44.911 [opensc-pkcs11] card.c:471:sc_lock: called
P:77260; T:0x34403866624 20:54:44.911 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:44.911 [opensc-pkcs11] apdu.c:515:sc_transmit: called
P:77260; T:0x34403866624 20:54:44.911 [opensc-pkcs11] apdu.c:363:sc_single_transmit: called
P:77260; T:0x34403866624 20:54:44.911 [opensc-pkcs11] apdu.c:370:sc_single_transmit: CLA:0, INS:DA, P1:0, P2:D0, data(4) 0x7fffdf3f5d5c
P:77260; T:0x34403866624 20:54:44.911 [opensc-pkcs11] reader-pcsc.c:325:pcsc_transmit: reader 'Nitrokey Nitrokey 3 [CCID/ICCD Interface] 00 00'
P:77260; T:0x34403866624 20:54:44.911 [opensc-pkcs11] reader-pcsc.c:326:pcsc_transmit: 
Outgoing APDU (9 bytes):
00 DA 00 D0 04 65 E8 AD E4 .....e...

P:77260; T:0x34403866624 20:54:44.912 [opensc-pkcs11] reader-pcsc.c:244:pcsc_internal_transmit: called
P:77260; T:0x34403866624 20:54:45.350 [opensc-pkcs11] reader-pcsc.c:335:pcsc_transmit: 
Incoming APDU (2 bytes):
90 00 ..

P:77260; T:0x34403866624 20:54:45.350 [opensc-pkcs11] apdu.c:382:sc_single_transmit: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:45.350 [opensc-pkcs11] apdu.c:539:sc_transmit: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:45.350 [opensc-pkcs11] card.c:523:sc_unlock: called
P:77260; T:0x34403866624 20:54:45.350 [opensc-pkcs11] card-openpgp.c:1971:pgp_put_data_plain: returning with: 4
P:77260; T:0x34403866624 20:54:45.350 [opensc-pkcs11] card-openpgp.c:2042:pgp_put_data: returning with: 4
P:77260; T:0x34403866624 20:54:45.350 [opensc-pkcs11] card-openpgp.c:2617:pgp_store_creationtime: returning with: 4
P:77260; T:0x34403866624 20:54:45.350 [opensc-pkcs11] card-openpgp.c:2952:pgp_parse_and_set_pubkey_output: Calculate and store fingerprint
P:77260; T:0x34403866624 20:54:45.350 [opensc-pkcs11] card-openpgp.c:2639:pgp_calculate_and_store_fingerprint: called
P:77260; T:0x34403866624 20:54:45.350 [opensc-pkcs11] card-openpgp.c:2692:pgp_calculate_and_store_fingerprint: pk_packet_len is 269
P:77260; T:0x34403866624 20:54:45.350 [opensc-pkcs11] card-openpgp.c:2774:pgp_calculate_and_store_fingerprint: Writing to DO 00C9.
P:77260; T:0x34403866624 20:54:45.350 [opensc-pkcs11] card-openpgp.c:1986:pgp_put_data: called
P:77260; T:0x34403866624 20:54:45.350 [opensc-pkcs11] card-openpgp.c:1632:pgp_get_pubkey: called, tag=b600
P:77260; T:0x34403866624 20:54:45.350 [opensc-pkcs11] apdu.c:550:sc_transmit_apdu: called
P:77260; T:0x34403866624 20:54:45.350 [opensc-pkcs11] card.c:471:sc_lock: called
P:77260; T:0x34403866624 20:54:45.350 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:45.350 [opensc-pkcs11] apdu.c:515:sc_transmit: called
P:77260; T:0x34403866624 20:54:45.350 [opensc-pkcs11] apdu.c:363:sc_single_transmit: called
P:77260; T:0x34403866624 20:54:45.351 [opensc-pkcs11] apdu.c:370:sc_single_transmit: CLA:0, INS:47, P1:81, P2:0, data(2) 0x7fffdf3f3896
P:77260; T:0x34403866624 20:54:45.351 [opensc-pkcs11] reader-pcsc.c:325:pcsc_transmit: reader 'Nitrokey Nitrokey 3 [CCID/ICCD Interface] 00 00'
P:77260; T:0x34403866624 20:54:45.351 [opensc-pkcs11] reader-pcsc.c:326:pcsc_transmit: 
Outgoing APDU (11 bytes):
00 47 81 00 00 00 02 B6 00 20 00 .G....... .

P:77260; T:0x34403866624 20:54:45.351 [opensc-pkcs11] reader-pcsc.c:244:pcsc_internal_transmit: called
P:77260; T:0x34403866624 20:54:45.406 [opensc-pkcs11] reader-pcsc.c:335:pcsc_transmit: 
Incoming APDU (2 bytes):
6A 88 j.

P:77260; T:0x34403866624 20:54:45.406 [opensc-pkcs11] apdu.c:382:sc_single_transmit: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:45.406 [opensc-pkcs11] apdu.c:539:sc_transmit: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:45.407 [opensc-pkcs11] card.c:523:sc_unlock: called
P:77260; T:0x34403866624 20:54:45.407 [opensc-pkcs11] iso7816.c:128:iso7816_check_sw: Referenced data not found
P:77260; T:0x34403866624 20:54:45.407 [opensc-pkcs11] card-openpgp.c:1646:pgp_get_pubkey: Card returned error: -1216 (Data object not found)
P:77260; T:0x34403866624 20:54:45.407 [opensc-pkcs11] card-openpgp.c:1632:pgp_get_pubkey: called, tag=b800
P:77260; T:0x34403866624 20:54:45.407 [opensc-pkcs11] apdu.c:550:sc_transmit_apdu: called
P:77260; T:0x34403866624 20:54:45.407 [opensc-pkcs11] card.c:471:sc_lock: called
P:77260; T:0x34403866624 20:54:45.407 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:45.407 [opensc-pkcs11] apdu.c:515:sc_transmit: called
P:77260; T:0x34403866624 20:54:45.407 [opensc-pkcs11] apdu.c:363:sc_single_transmit: called
P:77260; T:0x34403866624 20:54:45.407 [opensc-pkcs11] apdu.c:370:sc_single_transmit: CLA:0, INS:47, P1:81, P2:0, data(2) 0x7fffdf3f3896
P:77260; T:0x34403866624 20:54:45.407 [opensc-pkcs11] reader-pcsc.c:325:pcsc_transmit: reader 'Nitrokey Nitrokey 3 [CCID/ICCD Interface] 00 00'
P:77260; T:0x34403866624 20:54:45.407 [opensc-pkcs11] reader-pcsc.c:326:pcsc_transmit: 
Outgoing APDU (11 bytes):
00 47 81 00 00 00 02 B8 00 20 00 .G....... .

P:77260; T:0x34403866624 20:54:45.407 [opensc-pkcs11] reader-pcsc.c:244:pcsc_internal_transmit: called
P:77260; T:0x34403866624 20:54:45.463 [opensc-pkcs11] reader-pcsc.c:335:pcsc_transmit: 
Incoming APDU (2 bytes):
6A 88 j.

P:77260; T:0x34403866624 20:54:45.463 [opensc-pkcs11] apdu.c:382:sc_single_transmit: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:45.463 [opensc-pkcs11] apdu.c:539:sc_transmit: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:45.463 [opensc-pkcs11] card.c:523:sc_unlock: called
P:77260; T:0x34403866624 20:54:45.463 [opensc-pkcs11] iso7816.c:128:iso7816_check_sw: Referenced data not found
P:77260; T:0x34403866624 20:54:45.463 [opensc-pkcs11] card-openpgp.c:1646:pgp_get_pubkey: Card returned error: -1216 (Data object not found)
P:77260; T:0x34403866624 20:54:45.463 [opensc-pkcs11] card-openpgp.c:1399:pgp_find_blob: Failed to seek the blob representing the tag 00C9. Error -1201.
P:77260; T:0x34403866624 20:54:45.463 [opensc-pkcs11] card-openpgp.c:1938:pgp_put_data_plain: called
P:77260; T:0x34403866624 20:54:45.463 [opensc-pkcs11] apdu.c:550:sc_transmit_apdu: called
P:77260; T:0x34403866624 20:54:45.463 [opensc-pkcs11] card.c:471:sc_lock: called
P:77260; T:0x34403866624 20:54:45.463 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:45.463 [opensc-pkcs11] apdu.c:515:sc_transmit: called
P:77260; T:0x34403866624 20:54:45.463 [opensc-pkcs11] apdu.c:363:sc_single_transmit: called
P:77260; T:0x34403866624 20:54:45.464 [opensc-pkcs11] apdu.c:370:sc_single_transmit: CLA:0, INS:DA, P1:0, P2:C9, data(20) 0x7fffdf3f5d90
P:77260; T:0x34403866624 20:54:45.464 [opensc-pkcs11] reader-pcsc.c:325:pcsc_transmit: reader 'Nitrokey Nitrokey 3 [CCID/ICCD Interface] 00 00'
P:77260; T:0x34403866624 20:54:45.464 [opensc-pkcs11] reader-pcsc.c:326:pcsc_transmit: 
Outgoing APDU (25 bytes):
00 DA 00 C9 14 8F 8A C6 77 8B 7E FF 15 B9 88 27 ........w.~....'
FF C5 7E CF 3B B5 1C EC 4B                      ..~.;...K

P:77260; T:0x34403866624 20:54:45.464 [opensc-pkcs11] reader-pcsc.c:244:pcsc_internal_transmit: called
P:77260; T:0x34403866624 20:54:45.910 [opensc-pkcs11] reader-pcsc.c:335:pcsc_transmit: 
Incoming APDU (2 bytes):
90 00 ..

P:77260; T:0x34403866624 20:54:45.910 [opensc-pkcs11] apdu.c:382:sc_single_transmit: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:45.910 [opensc-pkcs11] apdu.c:539:sc_transmit: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:45.910 [opensc-pkcs11] card.c:523:sc_unlock: called
P:77260; T:0x34403866624 20:54:45.910 [opensc-pkcs11] card-openpgp.c:1971:pgp_put_data_plain: returning with: 20
P:77260; T:0x34403866624 20:54:45.910 [opensc-pkcs11] card-openpgp.c:2042:pgp_put_data: returning with: 20
P:77260; T:0x34403866624 20:54:45.910 [opensc-pkcs11] card-openpgp.c:2779:pgp_calculate_and_store_fingerprint: Updating fingerprint blob 00C5.
P:77260; T:0x34403866624 20:54:45.910 [opensc-pkcs11] card-openpgp.c:2800:pgp_calculate_and_store_fingerprint: returning with: 20
P:77260; T:0x34403866624 20:54:45.910 [opensc-pkcs11] card-openpgp.c:2956:pgp_parse_and_set_pubkey_output: Update blobs holding pubkey info.
P:77260; T:0x34403866624 20:54:45.911 [opensc-pkcs11] card-openpgp.c:2819:pgp_update_pubkey_blob: called
P:77260; T:0x34403866624 20:54:45.911 [opensc-pkcs11] card-openpgp.c:2832:pgp_update_pubkey_blob: Retrieving blob A401.
P:77260; T:0x34403866624 20:54:45.911 [opensc-pkcs11] pkcs15-pubkey.c:583:sc_pkcs15_encode_pubkey_rsa: called
P:77260; T:0x34403866624 20:54:45.911 [opensc-pkcs11] pkcs15-pubkey.c:594:sc_pkcs15_encode_pubkey_rsa: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:45.911 [opensc-pkcs11] card-openpgp.c:2860:pgp_update_pubkey_blob: Updating blob A401's content.
P:77260; T:0x34403866624 20:54:45.911 [opensc-pkcs11] card-openpgp.c:2864:pgp_update_pubkey_blob: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:45.911 [opensc-pkcs11] card-openpgp.c:2958:pgp_parse_and_set_pubkey_output: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:45.911 [opensc-pkcs11] card-openpgp.c:2972:pgp_update_card_algorithms: called
P:77260; T:0x34403866624 20:54:45.911 [opensc-pkcs11] card-openpgp.c:3001:pgp_update_card_algorithms: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:45.911 [opensc-pkcs11] card-openpgp.c:3101:pgp_gen_key: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:45.911 [opensc-pkcs11] card-openpgp.c:3598:pgp_card_ctl: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:45.911 [opensc-pkcs11] card.c:1129:sc_card_ctl: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:45.911 [opensc-pkcs11] pkcs15-openpgp.c:254:openpgp_generate_key_rsa: Set output modulus info
P:77260; T:0x34403866624 20:54:45.911 [opensc-pkcs11] pkcs15-openpgp.c:261:openpgp_generate_key_rsa: Set output exponent info
P:77260; T:0x34403866624 20:54:45.911 [opensc-pkcs11] pkcs15-openpgp.c:271:openpgp_generate_key_rsa: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:45.911 [opensc-pkcs11] pkcs15-openpgp.c:399:openpgp_generate_key: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:45.911 [opensc-pkcs11] pkcs15-lib.c:2795:sc_pkcs15init_select_intrinsic_id: called
P:77260; T:0x34403866624 20:54:45.911 [opensc-pkcs11] pkcs15-lib.c:2888:sc_pkcs15init_select_intrinsic_id: returning with: 20
P:77260; T:0x34403866624 20:54:45.911 [opensc-pkcs11] pkcs15-pubkey.c:583:sc_pkcs15_encode_pubkey_rsa: called
P:77260; T:0x34403866624 20:54:45.911 [opensc-pkcs11] pkcs15-pubkey.c:594:sc_pkcs15_encode_pubkey_rsa: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:45.911 [opensc-pkcs11] pkcs15-lib.c:3328:sc_pkcs15init_add_object: called
P:77260; T:0x34403866624 20:54:45.911 [opensc-pkcs11] pkcs15-lib.c:3329:sc_pkcs15init_add_object: add object 0x806045000 to DF of type 0
P:77260; T:0x34403866624 20:54:45.912 [opensc-pkcs11] pkcs15-lib.c:3353:sc_pkcs15init_add_object: Append object
P:77260; T:0x34403866624 20:54:45.912 [opensc-pkcs11] pkcs15-openpgp.c:405:openpgp_emu_update_any_df: called
P:77260; T:0x34403866624 20:54:45.912 [opensc-pkcs11] pkcs15-openpgp.c:408:openpgp_emu_update_any_df: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:45.912 [opensc-pkcs11] pkcs15-lib.c:3372:sc_pkcs15init_add_object: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:45.912 [opensc-pkcs11] pkcs15-openpgp.c:433:openpgp_store_data: called
P:77260; T:0x34403866624 20:54:45.912 [opensc-pkcs11] pkcs15-openpgp.c:524:openpgp_store_data: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:45.912 [opensc-pkcs11] pkcs15-lib.c:1865:sc_pkcs15init_store_public_key: called
P:77260; T:0x34403866624 20:54:45.912 [opensc-pkcs11] pkcs15-lib.c:2795:sc_pkcs15init_select_intrinsic_id: called
P:77260; T:0x34403866624 20:54:45.912 [opensc-pkcs11] pkcs15-lib.c:2804:sc_pkcs15init_select_intrinsic_id: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:45.912 [opensc-pkcs11] pkcs15-lib.c:2902:select_id: called
P:77260; T:0x34403866624 20:54:45.912 [opensc-pkcs11] pkcs15-lib.c:2912:select_id: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:45.912 [opensc-pkcs11] pkcs15-pubkey.c:583:sc_pkcs15_encode_pubkey_rsa: called
P:77260; T:0x34403866624 20:54:45.912 [opensc-pkcs11] pkcs15-pubkey.c:594:sc_pkcs15_encode_pubkey_rsa: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:45.912 [opensc-pkcs11] pkcs15-pubkey.c:583:sc_pkcs15_encode_pubkey_rsa: called
P:77260; T:0x34403866624 20:54:45.912 [opensc-pkcs11] pkcs15-pubkey.c:594:sc_pkcs15_encode_pubkey_rsa: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:45.912 [opensc-pkcs11] pkcs15-pubkey.c:776:sc_pkcs15_encode_pubkey_as_spki: called
P:77260; T:0x34403866624 20:54:45.912 [opensc-pkcs11] pkcs15-pubkey.c:780:sc_pkcs15_encode_pubkey_as_spki: Encoding public key with algorithm 0
P:77260; T:0x34403866624 20:54:45.912 [opensc-pkcs11] pkcs15-pubkey.c:583:sc_pkcs15_encode_pubkey_rsa: called
P:77260; T:0x34403866624 20:54:45.912 [opensc-pkcs11] pkcs15-pubkey.c:594:sc_pkcs15_encode_pubkey_rsa: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:45.912 [opensc-pkcs11] pkcs15-algo.c:535:sc_asn1_encode_algorithm_id: called
P:77260; T:0x34403866624 20:54:45.912 [opensc-pkcs11] pkcs15-algo.c:536:sc_asn1_encode_algorithm_id: type of algorithm to encode: 0
P:77260; T:0x34403866624 20:54:45.912 [opensc-pkcs11] pkcs15-algo.c:550:sc_asn1_encode_algorithm_id: encode algo 1.2.840.113549.1.1.1
P:77260; T:0x34403866624 20:54:45.912 [opensc-pkcs11] pkcs15-algo.c:589:sc_asn1_encode_algorithm_id: return encoded algorithm ID: 06092A864886F70D0101010500
P:77260; T:0x34403866624 20:54:45.913 [opensc-pkcs11] pkcs15-algo.c:590:sc_asn1_encode_algorithm_id: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:45.913 [opensc-pkcs11] pkcs15-pubkey.c:856:sc_pkcs15_encode_pubkey_as_spki: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:45.913 [opensc-pkcs11] pkcs15-lib.c:2406:sc_pkcs15init_store_data: called
P:77260; T:0x34403866624 20:54:45.913 [opensc-pkcs11] pkcs15-openpgp.c:433:openpgp_store_data: called
P:77260; T:0x34403866624 20:54:45.913 [opensc-pkcs11] pkcs15-openpgp.c:524:openpgp_store_data: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:45.913 [opensc-pkcs11] pkcs15-lib.c:2411:sc_pkcs15init_store_data: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:45.913 [opensc-pkcs11] pkcs15-lib.c:3328:sc_pkcs15init_add_object: called
P:77260; T:0x34403866624 20:54:45.913 [opensc-pkcs11] pkcs15-lib.c:3329:sc_pkcs15init_add_object: add object 0x806045c00 to DF of type 1
P:77260; T:0x34403866624 20:54:45.913 [opensc-pkcs11] pkcs15-lib.c:3353:sc_pkcs15init_add_object: Append object
P:77260; T:0x34403866624 20:54:45.913 [opensc-pkcs11] pkcs15-openpgp.c:405:openpgp_emu_update_any_df: called
P:77260; T:0x34403866624 20:54:45.913 [opensc-pkcs11] pkcs15-openpgp.c:408:openpgp_emu_update_any_df: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:45.913 [opensc-pkcs11] pkcs15-lib.c:3372:sc_pkcs15init_add_object: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:45.913 [opensc-pkcs11] pkcs15-lib.c:2033:sc_pkcs15init_store_public_key: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:45.913 [opensc-pkcs11] pkcs15-lib.c:1680:sc_pkcs15init_generate_key: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:45.913 [opensc-pkcs11] framework-pkcs15.c:753:__pkcs15_create_pubkey_object: Get pubkey from PKCS#15 object
P:77260; T:0x34403866624 20:54:45.913 [opensc-pkcs11] pkcs15-pubkey.c:900:sc_pkcs15_read_pubkey: called
P:77260; T:0x34403866624 20:54:45.913 [opensc-pkcs11] pkcs15-pubkey.c:901:sc_pkcs15_read_pubkey: Public key type 0x201
P:77260; T:0x34403866624 20:54:45.913 [opensc-pkcs11] pkcs15-pubkey.c:933:sc_pkcs15_read_pubkey: Using direct SPKI value,  tag 0x30
P:77260; T:0x34403866624 20:54:45.913 [opensc-pkcs11] pkcs15-pubkey.c:1438:sc_pkcs15_pubkey_from_spki_sequence: called
P:77260; T:0x34403866624 20:54:45.913 [opensc-pkcs11] pkcs15-pubkey.c:1328:sc_pkcs15_pubkey_from_spki_fields: sc_pkcs15_pubkey_from_spki_fields() called: 0x80604e504:290
300D06092A864886F70D010101050003 82010F003082010A0282010100CFE23D B65637F22C5002841D92EAA181CD626D
F441853762742F06C66743EF2A876701 CCDFD92F2874427722331773FDECD807 21E491FE099BB17A3471401624DCB7AB
08772E4FC80170EC1EB0765E56AF8B14 7D25868C8E691D5298EFD286C2655986 0733CE49A233857A84BF9089FF83984C
AA40A68B3E5A522E1E19A90446E56F7F A22DB3A7D2D087985F25A04A4CB3E3C3 55B3DC6D841330D4C5077E7F23E74ADB
253E9A27007968429ED3B3F6B8172CA3 30D000A29B1D77E8419D9DEF5831FD6C F6ECD5CB6376CFC57431806CBCE2F276
03871FD984A7F5926B12FB2AB74DE3C4 6BD0AD144FEF3DD56427EE9B8EABA48D 5E60C4FDF31490C5A8DC25232D020301
0001
P:77260; T:0x34403866624 20:54:45.914 [opensc-pkcs11] pkcs15-algo.c:494:sc_asn1_decode_algorithm_id: called
P:77260; T:0x34403866624 20:54:45.914 [opensc-pkcs11] pkcs15-algo.c:502:sc_asn1_decode_algorithm_id: decoded OID '1.2.840.113549.1.1.1'
P:77260; T:0x34403866624 20:54:45.914 [opensc-pkcs11] pkcs15-algo.c:519:sc_asn1_decode_algorithm_id: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:45.914 [opensc-pkcs11] pkcs15-pubkey.c:1367:sc_pkcs15_pubkey_from_spki_fields: DEE pk_alg.algorithm=0
P:77260; T:0x34403866624 20:54:45.914 [opensc-pkcs11] pkcs15-pubkey.c:560:sc_pkcs15_decode_pubkey_rsa: called
P:77260; T:0x34403866624 20:54:45.914 [opensc-pkcs11] pkcs15-pubkey.c:571:sc_pkcs15_decode_pubkey_rsa: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:45.914 [opensc-pkcs11] pkcs15-pubkey.c:1424:sc_pkcs15_pubkey_from_spki_fields: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:45.914 [opensc-pkcs11] pkcs15-pubkey.c:1449:sc_pkcs15_pubkey_from_spki_sequence: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:45.914 [opensc-pkcs11] pkcs15-pubkey.c:984:sc_pkcs15_read_pubkey: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:45.914 [opensc-pkcs11] framework-pkcs15.c:1064:pkcs15_add_object: Slot:0 Setting object handle of 0x0 to 0x80600b060
P:77260; T:0x34403866624 20:54:45.914 [opensc-pkcs11] framework-pkcs15.c:1064:pkcs15_add_object: Slot:0 Setting object handle of 0x0 to 0x80600b0c0
P:77260; T:0x34403866624 20:54:45.914 [opensc-pkcs11] pkcs15-pubkey.c:1079:sc_pkcs15_dup_pubkey: called
P:77260; T:0x34403866624 20:54:45.914 [opensc-pkcs11] pkcs15-algo.c:535:sc_asn1_encode_algorithm_id: called
P:77260; T:0x34403866624 20:54:45.914 [opensc-pkcs11] pkcs15-algo.c:536:sc_asn1_encode_algorithm_id: type of algorithm to encode: 0
P:77260; T:0x34403866624 20:54:45.914 [opensc-pkcs11] pkcs15-algo.c:550:sc_asn1_encode_algorithm_id: encode algo 1.2.840.113549.1.1.1
P:77260; T:0x34403866624 20:54:45.914 [opensc-pkcs11] pkcs15-algo.c:589:sc_asn1_encode_algorithm_id: return encoded algorithm ID: 06092A864886F70D0101010500
P:77260; T:0x34403866624 20:54:45.914 [opensc-pkcs11] pkcs15-algo.c:590:sc_asn1_encode_algorithm_id: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:45.914 [opensc-pkcs11] pkcs15-algo.c:494:sc_asn1_decode_algorithm_id: called
P:77260; T:0x34403866624 20:54:45.914 [opensc-pkcs11] pkcs15-algo.c:502:sc_asn1_decode_algorithm_id: decoded OID '1.2.840.113549.1.1.1'
P:77260; T:0x34403866624 20:54:45.914 [opensc-pkcs11] pkcs15-algo.c:519:sc_asn1_decode_algorithm_id: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:45.914 [opensc-pkcs11] pkcs15-pubkey.c:1163:sc_pkcs15_dup_pubkey: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:45.914 [opensc-pkcs11] pkcs15-lib.c:438:sc_pkcs15init_unbind: called
P:77260; T:0x34403866624 20:54:45.915 [opensc-pkcs11] pkcs15-lib.c:439:sc_pkcs15init_unbind: Pksc15init Unbind: 1:0x805c01280:1
P:77260; T:0x34403866624 20:54:45.915 [opensc-pkcs11] pkcs15-lib.c:3200:sc_pkcs15init_update_lastupdate: called
P:77260; T:0x34403866624 20:54:45.915 [opensc-pkcs11] pkcs15-lib.c:3166:sc_pkcs15init_update_tokeninfo: called
P:77260; T:0x34403866624 20:54:45.915 [opensc-pkcs11] pkcs15-openpgp.c:414:openpgp_emu_update_tokeninfo: called
P:77260; T:0x34403866624 20:54:45.915 [opensc-pkcs11] pkcs15-openpgp.c:417:openpgp_emu_update_tokeninfo: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:45.915 [opensc-pkcs11] pkcs15-lib.c:3240:sc_pkcs15init_update_lastupdate: returning with: 0 (Success)
P:77260; T:0x34403866624 20:54:45.915 [opensc-pkcs11] card.c:523:sc_unlock: called
P:77260; T:0x34403866624 20:54:45.915 [opensc-pkcs11] card.c:523:sc_unlock: called
P:77260; T:0x34403866624 20:54:45.915 [opensc-pkcs11] reader-pcsc.c:742:pcsc_unlock: called
Act IV: Getting the public key again
P:77260; T:0x34403852288 20:56:39.830 [opensc-pkcs11] card.c:471:sc_lock: called
P:77260; T:0x34403852288 20:56:39.830 [opensc-pkcs11] reader-pcsc.c:690:pcsc_lock: called
P:77260; T:0x34403852288 20:56:39.830 [opensc-pkcs11] card-openpgp.c:3745:pgp_card_reader_lock_obtained: called
P:77260; T:0x34403852288 20:56:39.830 [opensc-pkcs11] card-openpgp.c:3772:pgp_card_reader_lock_obtained: returning with: 0 (Success)
P:77260; T:0x34403852288 20:56:39.830 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:77260; T:0x34403852288 20:56:39.830 [opensc-pkcs11] pkcs11-object.c:377:C_FindObjectsInit: C_FindObjectsInit(slot = 0)
P:77260; T:0x34403852288 20:56:39.830 [opensc-pkcs11] pkcs11-object.c:378:C_FindObjectsInit: C_FindObjectsInit(): CKA_ENCRYPT = TRUE
P:77260; T:0x34403852288 20:56:39.831 [opensc-pkcs11] misc.c:267:session_start_operation: called
P:77260; T:0x34403852288 20:56:39.831 [opensc-pkcs11] misc.c:268:session_start_operation: Session 0x806011150, type 0
P:77260; T:0x34403852288 20:56:39.831 [opensc-pkcs11] pkcs11-object.c:400:C_FindObjectsInit: Object with handle 0x805c0b240
P:77260; T:0x34403852288 20:56:39.831 [opensc-pkcs11] framework-pkcs15.c:4000:pkcs15_prkey_get_attribute: pkcs15_prkey_get_attribute() called
P:77260; T:0x34403852288 20:56:39.831 [opensc-pkcs11] pkcs11-object.c:421:C_FindObjectsInit: Object 0/34456252992: Attribute 0x104 does NOT match.
P:77260; T:0x34403852288 20:56:39.831 [opensc-pkcs11] pkcs11-object.c:400:C_FindObjectsInit: Object with handle 0x805c0b1e0
P:77260; T:0x34403852288 20:56:39.831 [opensc-pkcs11] framework-pkcs15.c:4891:pkcs15_pubkey_get_attribute: pkcs15_pubkey_get_attribute() called
P:77260; T:0x34403852288 20:56:39.831 [opensc-pkcs11] framework-pkcs15.c:4891:pkcs15_pubkey_get_attribute: pkcs15_pubkey_get_attribute() called
P:77260; T:0x34403852288 20:56:39.831 [opensc-pkcs11] pkcs11-object.c:435:C_FindObjectsInit: Object 0/34456252896 matches
P:77260; T:0x34403852288 20:56:39.831 [opensc-pkcs11] pkcs11-object.c:439:C_FindObjectsInit: realloc for 32 handles
P:77260; T:0x34403852288 20:56:39.831 [opensc-pkcs11] pkcs11-object.c:400:C_FindObjectsInit: Object with handle 0x805c23050
P:77260; T:0x34403852288 20:56:39.831 [opensc-pkcs11] framework-pkcs15.c:5328:pkcs15_profile_get_attribute: pkcs15_profile_get_attribute() called
P:77260; T:0x34403852288 20:56:39.831 [opensc-pkcs11] pkcs11-object.c:421:C_FindObjectsInit: Object 0/34456350800: Attribute 0x104 does NOT match.
P:77260; T:0x34403852288 20:56:39.831 [opensc-pkcs11] pkcs11-object.c:400:C_FindObjectsInit: Object with handle 0x80600b060
P:77260; T:0x34403852288 20:56:39.831 [opensc-pkcs11] framework-pkcs15.c:4000:pkcs15_prkey_get_attribute: pkcs15_prkey_get_attribute() called
P:77260; T:0x34403852288 20:56:39.831 [opensc-pkcs11] pkcs11-object.c:421:C_FindObjectsInit: Object 0/34460446816: Attribute 0x104 does NOT match.
P:77260; T:0x34403852288 20:56:39.831 [opensc-pkcs11] pkcs11-object.c:400:C_FindObjectsInit: Object with handle 0x80600b0c0
P:77260; T:0x34403852288 20:56:39.831 [opensc-pkcs11] framework-pkcs15.c:4891:pkcs15_pubkey_get_attribute: pkcs15_pubkey_get_attribute() called
P:77260; T:0x34403852288 20:56:39.831 [opensc-pkcs11] framework-pkcs15.c:4891:pkcs15_pubkey_get_attribute: pkcs15_pubkey_get_attribute() called
P:77260; T:0x34403852288 20:56:39.831 [opensc-pkcs11] pkcs11-object.c:421:C_FindObjectsInit: Object 0/34460446912: Attribute 0x104 does NOT match.
P:77260; T:0x34403852288 20:56:39.831 [opensc-pkcs11] pkcs11-object.c:452:C_FindObjectsInit: 1 matching objects
P:77260; T:0x34403852288 20:56:39.831 [opensc-pkcs11] misc.c:289:session_get_operation: called
P:77260; T:0x34403852288 20:56:39.831 [opensc-pkcs11] misc.c:289:session_get_operation: called
P:77260; T:0x34403852288 20:56:39.831 [opensc-pkcs11] framework-pkcs15.c:4891:pkcs15_pubkey_get_attribute: pkcs15_pubkey_get_attribute() called
P:77260; T:0x34403852288 20:56:39.831 [opensc-pkcs11] pkcs11-object.c:270:C_GetAttributeValue: Object 34456252896: CKA_MODULUS = <size inquiry>
P:77260; T:0x34403852288 20:56:39.831 [opensc-pkcs11] pkcs11-object.c:295:C_GetAttributeValue: C_GetAttributeValue(hSession=0x806011150, hObject=0x805c0b1e0) = CKR_OK
P:77260; T:0x34403852288 20:56:39.832 [opensc-pkcs11] framework-pkcs15.c:4891:pkcs15_pubkey_get_attribute: pkcs15_pubkey_get_attribute() called
P:77260; T:0x34403852288 20:56:39.832 [opensc-pkcs11] pkcs11-object.c:270:C_GetAttributeValue: Object 34456252896: CKA_MODULUS = D771D9DE31F225C15891D08ADA2B5BBBB024E7D2345140A552DA12B3FFECE34B
P:77260; T:0x34403852288 20:56:39.832 [opensc-pkcs11] pkcs11-object.c:295:C_GetAttributeValue: C_GetAttributeValue(hSession=0x806011150, hObject=0x805c0b1e0) = CKR_OK
P:77260; T:0x34403852288 20:56:39.832 [opensc-pkcs11] framework-pkcs15.c:4891:pkcs15_pubkey_get_attribute: pkcs15_pubkey_get_attribute() called
P:77260; T:0x34403852288 20:56:39.832 [opensc-pkcs11] pkcs11-object.c:270:C_GetAttributeValue: Object 34456252896: CKA_PUBLIC_EXPONENT = <size inquiry>
P:77260; T:0x34403852288 20:56:39.832 [opensc-pkcs11] pkcs11-object.c:295:C_GetAttributeValue: C_GetAttributeValue(hSession=0x806011150, hObject=0x805c0b1e0) = CKR_OK
P:77260; T:0x34403852288 20:56:39.832 [opensc-pkcs11] framework-pkcs15.c:4891:pkcs15_pubkey_get_attribute: pkcs15_pubkey_get_attribute() called
P:77260; T:0x34403852288 20:56:39.832 [opensc-pkcs11] pkcs11-object.c:270:C_GetAttributeValue: Object 34456252896: CKA_PUBLIC_EXPONENT = 010001
P:77260; T:0x34403852288 20:56:39.832 [opensc-pkcs11] pkcs11-object.c:295:C_GetAttributeValue: C_GetAttributeValue(hSession=0x806011150, hObject=0x805c0b1e0) = CKR_OK
P:77260; T:0x34403852288 20:56:39.832 [opensc-pkcs11] card.c:523:sc_unlock: called
P:77260; T:0x34403852288 20:56:39.832 [opensc-pkcs11] reader-pcsc.c:742:pcsc_unlock: called

Note that CKA_MODULUS = D771D9DE31F225C15891D08ADA2B5BBBB024E7D2345140A552DA12B3FFECE34B matches the first call.

Act V: Getting the public key after token reinsertion (skipping the initialization log)
P:77260; T:0x34403852288 20:57:29.794 [opensc-pkcs11] card.c:471:sc_lock: called
P:77260; T:0x34403852288 20:57:29.794 [opensc-pkcs11] reader-pcsc.c:690:pcsc_lock: called
P:77260; T:0x34403852288 20:57:29.794 [opensc-pkcs11] card-openpgp.c:3745:pgp_card_reader_lock_obtained: called
P:77260; T:0x34403852288 20:57:29.794 [opensc-pkcs11] card-openpgp.c:3772:pgp_card_reader_lock_obtained: returning with: 0 (Success)
P:77260; T:0x34403852288 20:57:29.794 [opensc-pkcs11] card.c:513:sc_lock: returning with: 0 (Success)
P:77260; T:0x34403852288 20:57:29.794 [opensc-pkcs11] pkcs11-object.c:377:C_FindObjectsInit: C_FindObjectsInit(slot = 0)
P:77260; T:0x34403852288 20:57:29.794 [opensc-pkcs11] pkcs11-object.c:378:C_FindObjectsInit: C_FindObjectsInit(): CKA_ENCRYPT = TRUE
P:77260; T:0x34403852288 20:57:29.794 [opensc-pkcs11] misc.c:267:session_start_operation: called
P:77260; T:0x34403852288 20:57:29.794 [opensc-pkcs11] misc.c:268:session_start_operation: Session 0x806011310, type 0
P:77260; T:0x34403852288 20:57:29.794 [opensc-pkcs11] pkcs11-object.c:400:C_FindObjectsInit: Object with handle 0x805c0b1e0
P:77260; T:0x34403852288 20:57:29.794 [opensc-pkcs11] framework-pkcs15.c:4000:pkcs15_prkey_get_attribute: pkcs15_prkey_get_attribute() called
P:77260; T:0x34403852288 20:57:29.794 [opensc-pkcs11] pkcs11-object.c:409:C_FindObjectsInit: Object 0/34456252896: Private object and not logged in.
P:77260; T:0x34403852288 20:57:29.794 [opensc-pkcs11] pkcs11-object.c:400:C_FindObjectsInit: Object with handle 0x805c0b240
P:77260; T:0x34403852288 20:57:29.794 [opensc-pkcs11] framework-pkcs15.c:4891:pkcs15_pubkey_get_attribute: pkcs15_pubkey_get_attribute() called
P:77260; T:0x34403852288 20:57:29.794 [opensc-pkcs11] framework-pkcs15.c:4891:pkcs15_pubkey_get_attribute: pkcs15_pubkey_get_attribute() called
P:77260; T:0x34403852288 20:57:29.794 [opensc-pkcs11] framework-pkcs15.c:4891:pkcs15_pubkey_get_attribute: pkcs15_pubkey_get_attribute() called
P:77260; T:0x34403852288 20:57:29.795 [opensc-pkcs11] pkcs11-object.c:435:C_FindObjectsInit: Object 0/34456252992 matches
P:77260; T:0x34403852288 20:57:29.795 [opensc-pkcs11] pkcs11-object.c:439:C_FindObjectsInit: realloc for 32 handles
P:77260; T:0x34403852288 20:57:29.795 [opensc-pkcs11] pkcs11-object.c:400:C_FindObjectsInit: Object with handle 0x806019000
P:77260; T:0x34403852288 20:57:29.795 [opensc-pkcs11] framework-pkcs15.c:5328:pkcs15_profile_get_attribute: pkcs15_profile_get_attribute() called
P:77260; T:0x34403852288 20:57:29.795 [opensc-pkcs11] framework-pkcs15.c:5328:pkcs15_profile_get_attribute: pkcs15_profile_get_attribute() called
P:77260; T:0x34403852288 20:57:29.795 [opensc-pkcs11] pkcs11-object.c:421:C_FindObjectsInit: Object 0/34460504064: Attribute 0x104 does NOT match.
P:77260; T:0x34403852288 20:57:29.795 [opensc-pkcs11] pkcs11-object.c:452:C_FindObjectsInit: 1 matching objects
P:77260; T:0x34403852288 20:57:29.795 [opensc-pkcs11] misc.c:289:session_get_operation: called
P:77260; T:0x34403852288 20:57:29.795 [opensc-pkcs11] misc.c:289:session_get_operation: called
P:77260; T:0x34403852288 20:57:29.795 [opensc-pkcs11] framework-pkcs15.c:4891:pkcs15_pubkey_get_attribute: pkcs15_pubkey_get_attribute() called
P:77260; T:0x34403852288 20:57:29.795 [opensc-pkcs11] pkcs11-object.c:270:C_GetAttributeValue: Object 34456252992: CKA_MODULUS = <size inquiry>
P:77260; T:0x34403852288 20:57:29.795 [opensc-pkcs11] pkcs11-object.c:295:C_GetAttributeValue: C_GetAttributeValue(hSession=0x806011310, hObject=0x805c0b240) = CKR_OK
P:77260; T:0x34403852288 20:57:29.795 [opensc-pkcs11] framework-pkcs15.c:4891:pkcs15_pubkey_get_attribute: pkcs15_pubkey_get_attribute() called
P:77260; T:0x34403852288 20:57:29.795 [opensc-pkcs11] pkcs11-object.c:270:C_GetAttributeValue: Object 34456252992: CKA_MODULUS = CFE23DB65637F22C5002841D92EAA181CD626DF441853762742F06C66743EF2A
P:77260; T:0x34403852288 20:57:29.795 [opensc-pkcs11] pkcs11-object.c:295:C_GetAttributeValue: C_GetAttributeValue(hSession=0x806011310, hObject=0x805c0b240) = CKR_OK
P:77260; T:0x34403852288 20:57:29.795 [opensc-pkcs11] framework-pkcs15.c:4891:pkcs15_pubkey_get_attribute: pkcs15_pubkey_get_attribute() called
P:77260; T:0x34403852288 20:57:29.795 [opensc-pkcs11] pkcs11-object.c:270:C_GetAttributeValue: Object 34456252992: CKA_PUBLIC_EXPONENT = <size inquiry>
P:77260; T:0x34403852288 20:57:29.795 [opensc-pkcs11] pkcs11-object.c:295:C_GetAttributeValue: C_GetAttributeValue(hSession=0x806011310, hObject=0x805c0b240) = CKR_OK
P:77260; T:0x34403852288 20:57:29.795 [opensc-pkcs11] framework-pkcs15.c:4891:pkcs15_pubkey_get_attribute: pkcs15_pubkey_get_attribute() called
P:77260; T:0x34403852288 20:57:29.795 [opensc-pkcs11] pkcs11-object.c:270:C_GetAttributeValue: Object 34456252992: CKA_PUBLIC_EXPONENT = 010001
P:77260; T:0x34403852288 20:57:29.795 [opensc-pkcs11] pkcs11-object.c:295:C_GetAttributeValue: C_GetAttributeValue(hSession=0x806011310, hObject=0x805c0b240) = CKR_OK
P:77260; T:0x34403852288 20:57:29.795 [opensc-pkcs11] card.c:523:sc_unlock: called
P:77260; T:0x34403852288 20:57:29.795 [opensc-pkcs11] reader-pcsc.c:742:pcsc_unlock: called

CKA_MODULUS now different!

@frankmorgner
Copy link
Member

You are basically replacing an old key with a new key, which is not what C_GenerateKeyPair does. It only creates objects and, in particular, we should actually return an error in your case:

  1. If the supplied template specifies an invalid value for a valid attribute, then the attempt should fail with the error code CKR_ATTRIBUTE_VALUE_INVALID.
    

sc_pkcs15init_generate_key() does not automatically delete or replace existing objects. Although this technically works with the given card, I think you should manually call C_DestroyObject before creating a new key with that same ID.

Maybe we should check the ID for an existing object and return CKR_ATTRIBUTE_VALUE_INVALID in that case, but I'm not sure if we need to be so strict.

@arrowd
Copy link
Author

arrowd commented Mar 7, 2024

Oh, that makes sense. I will try adding appropriate C_DestroyObject call[s], thank you.

@arrowd
Copy link
Author

arrowd commented Mar 12, 2024

I tried the C_DestroyObject suggestion, but it didn't work out for me. Before I dive into producing OpenSC debug output, here's what I did.

Right before the C_GenerateKeyPair call I put the following code:

    CK_OBJECT_CLASS classes[] = { CKO_PUBLIC_KEY, CKO_PRIVATE_KEY, CKO_PROFILE, CKO_CERTIFICATE };

    for (auto klass : classes) {
        CK_ATTRIBUTE attrs[] =
        {
            { CKA_CLASS, &klass, sizeof(klass) },
        };
        auto rv = m_p11->C_FindObjectsInit(m_sessionHandle, attrs, sizeof(attrs) / sizeof(CK_ATTRIBUTE));
        if (rv != CKR_OK) {
            qDebug() << "deleteAllObjects: C_FindObjectsInit(" << klass << "):" << rv;
            continue;
        }

        // FIXME: this will leave some objects if their total number is greater than SK_MAX_OBJECTS
        CK_OBJECT_HANDLE objs[SK_MAX_OBJECTS];
        CK_ULONG outSize = 0;
        rv = m_p11->C_FindObjects(m_sessionHandle, objs, SK_MAX_OBJECTS, &outSize);
        if (rv != CKR_OK) {
            qDebug() << "deleteAllObjects: C_FindObjects(" << klass << "):" << rv;
            m_p11->C_FindObjectsFinal(m_sessionHandle);
            continue;
        }

        while (outSize > 0) {
            rv = m_p11->C_DestroyObject(m_sessionHandle, objs[outSize-1]);
            if (rv != CKR_OK)
                qDebug() << "deleteAllObjects: C_DestroyObject(" << klass << "):" << rv;
            outSize--;
        }

        m_p11->C_FindObjectsFinal(m_sessionHandle);
    }

When running this I only got deleteAllObjects: C_DestroyObject( 9 ): 84, which is probably fine. However, after the generation finished calling C_FindObjectsInit+C_FindObjects+C_FindObjectsFinal with the { CKA_ENCRYPT, &_true, sizeof(_true) } template yield nothing. Reinserting the token made it work again.

@frankmorgner
Copy link
Member

I think it would be good to open a new issue for that, with a) a pkcs11-spy trace to see the order of commands and b) an opensc debug log to see what's happening under the hood. thank you.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants