It looks like oseid tests are consistently failing with file caching enabled by default. @popovec , do you have an Idea how to avoid that?

I will try to find where the problem is, here debug if cache is enabled:

P:922036; T:0x140389957015360 19:14:42.962 [pkcs15-init] pkcs15-myeid.c:601:myeid_create_key: Key file size 768
P:922036; T:0x140389957015360 19:14:42.962 [pkcs15-init] pkcs15-myeid.c:608:myeid_create_key: Path of MyEID key file to create 3f0050154b01
P:922036; T:0x140389957015360 19:14:42.962 [pkcs15-init] pkcs15-myeid.c:616:myeid_create_key: Failed to get pin object by auth_id: -1407 (Requested object not found)

and if cache is disabled:

P:923202; T:0x140312879388480 19:20:58.205 [pkcs15-init] pkcs15-myeid.c:601:myeid_create_key: Key file size 768
P:923202; T:0x140312879388480 19:20:58.206 [pkcs15-init] pkcs15-myeid.c:608:myeid_create_key: Path of MyEID key file to create 3f0050154b01
P:923202; T:0x140312879388480 19:20:58.206 [pkcs15-init] pkcs15-lib.c:3947:sc_pkcs15init_create_file: called
P:923202; T:0x140312879388480 19:20:58.206 [pkcs15-init] pkcs15-lib.c:3952:sc_pkcs15init_create_file: create file '3f0050154b01'
P:923202; T:0x140312879388480 19:20:58.206 [pkcs15-init] pkcs15-lib.c:3898:do_select_parent: called

I was looking for where the pin object by auth_id fails .. it ends with an error in sc_pkcs15_compare_id () where it compares 0xff to 0x01.

I started looking at the cache and the real contents of the file in the card during card initialization.

$ rm  .cache/opensc/*
$ pkcs15-init -C --so-pin 00000000 --so-puk 00000000
$ ls .cache/opensc/
$  pkcs15-init --store-pin --id 01 --pin 11111111 --puk 11111111 --so-pin 00000000
$ ls .cache/opensc/
00000000000000000001_20220131191724Z_50154401
$ hd .cache/opensc/00000000000000000001_20220131191724Z_50154401
00000000  30 3b 30 1a 0c 14 53 65  63 75 72 69 74 79 20 4f  |0;0...Security O|
00000010  66 66 69 63 65 72 20 50  49 4e 03 02 06 c0 30 03  |fficer PIN....0.|
00000020  04 01 ff a1 18 30 16 03  02 00 0d 0a 01 01 02 01  |.....0..........|
00000030  04 02 01 08 02 01 08 80  01 03 04 01 ff ff ff ff  |................|
00000040  ff ff ff ff ff ff ff ff  ff ff ff ff ff ff ff ff  |................|
*
000000f0  ff ff ff ff ff ff ff ff  ff ff ff ff ff ff ff     |...............|
000000ff

Something is wrong, this "cached" file is incomplete.

$ opensc-explorer 
OpenSC Explorer version 0.22.0
Using reader with a card: OsEIDsim 00 00
OpenSC [3F00]> cd 5015
OpenSC [3F00/5015]> ls
FileID  Type  Size
 4402    wEF  1530
 5031    wEF   255
 4404    wEF  1530
 4407    wEF  1530
 4403    wEF  1530
 4405    wEF   510
 4406    wEF  1530
 4401    wEF   255
 5032    wEF   180
 4946    wEF   128
OpenSC [3F00/5015]> cat 4401
00000000: 30 3B 30 1A 0C 14 53 65 63 75 72 69 74 79 20 4F 0;0...Security O
00000010: 66 66 69 63 65 72 20 50 49 4E 03 02 06 C0 30 03 fficer PIN....0.
00000020: 04 01 FF A1 18 30 16 03 02 00 0D 0A 01 01 02 01 .....0..........
00000030: 04 02 01 08 02 01 08 80 01 03 04 01 FF 30 25 30 .............0%0
00000040: 04 03 02 06 C0 30 03 04 01 01 A1 18 30 16 03 02 .....0......0...
00000050: 02 0C 0A 01 01 02 01 04 02 01 08 02 01 08 80 01 ................
00000060: 01 04 01 FF 00 00 00 00 00 00 00 00 00 00 00 00 ................
00000070: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
00000080: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
00000090: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
000000A0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
000000B0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
000000C0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
000000D0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
000000E0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
000000F0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00    ...............
OpenSC [3F00/5015]> 

I have not yet found where the problem is that the cache does not match the contents of the card. However, OsEID uses one special thing, the empty file is filled with the value 0xff and not with the value 0x00.

So I checked the MyEID (4.5.5) card (empty file is filled by 0x00), but I found same problem - Failed to store private key: Requested object not found.

cached file:

$ hd .cache/opensc/00009276009757075378_20220131195127Z_50154401 
00000000  30 3b 30 1a 0c 14 53 65  63 75 72 69 74 79 20 4f  |0;0...Security O|
00000010  66 66 69 63 65 72 20 50  49 4e 03 02 06 c0 30 03  |fficer PIN....0.|
00000020  04 01 ff a1 18 30 16 03  02 00 0d 0a 01 01 02 01  |.....0..........|
00000030  04 02 01 08 02 01 08 80  01 03 04 01 ff 00 00 00  |................|
00000040  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
*
000000ff

The User pin is missing. Of course, real file is correct (same as in opensc-explorer dump above). I have no idea where the cache is failing.

For the cache to work normally, the update tokeninfo must be enabled:

diff --git a/src/pkcs15init/myeid.profile b/src/pkcs15init/myeid.profile
index fb2dc7c0..ffac44a8 100644
--- a/src/pkcs15init/myeid.profile
+++ b/src/pkcs15init/myeid.profile
@@ -21,7 +21,7 @@ pkcs15 {
     # Put the DF length into the ODF file?
     encode-df-length    = no;
     # Have a lastUpdate field in the EF(TokenInfo)?
-    do-last-update         = no;
+    do-last-update         = yes;
 }

But that's not all, since the resolution for the update date is only in seconds, the cache does not have the correct data if something is updated more than once in one second. An example is the initialization:

pkcs11-init -C ...
pkcs11-tool --store-pin ..

If this happens in one second (for script files it happens in 99% of cases), the cache responds incorrectly (data is out of date).
I can add a one-second delay into the OsEID-tool to pass the tests, but it will only be a workaround.

diff --git a/OsEID-tool b/OsEID-tool
index 79ded00..c47faf2 100755
--- a/OsEID-tool
+++ b/OsEID-tool
@@ -529,6 +529,8 @@ if [ $? -ne 0 ]; then
 fi
 echo "pkcs15-init OK"
 echo "initializing user (01) PIN=11111111 PUK=11111111"
+# delay pin initialization (workaround for opensc cache)
+sleep 1
 #this is needed to get access to private key for sign/cipher op
 PKCS15-INIT --store-pin --id 01 --pin 11111111 --puk 11111111 --so-pin 00000000
 if [ $? -ne 0 ]; then

I assume that if the cache does not have a time resolution of at least milliseconds, it will cause us a problem elsewhere as well.

Thank you for the investigation! I noticed this before, but I did not have good enough reproducer to fill a bug report so I disabled file cache in pkcs15-init tool in Fedora with opensc.conf:

app pkcs15-init {
  framework pkcs15 {
    use_file_caching = false;
  }
}

https://src.fedoraproject.org/rpms/opensc/blob/rawhide/f/opensc-0.22.0-file-cache.patch

Would it be an option if the driver invalidated/deleted the cache in case it writes to the card or something? Or do I understand the problem wrong?

Yes, I'm also considering the possibility that any write to the card would invalidate the cache. It is the easiest implementable option. All you have to do is delete the file from the cache for put-data, update-binary, etc. operations.

However, we must have an active "do-last-update", because we can add new keys on one computer and they would not appear on the other computer (the cache would not be invalidated). In this case, a cache time resolution of 1 second will suffice. Still there exists race condition, if a card is updated from two concurrent tasks that use a different cache...

There is another option to maintain the cache, but it will not be universal. The MyEID card contains a counter, where each write operation increments the counter. This could be used instead of "last-update" information. But I have no idea if we have similar information from other cards.

Yes, I'm also considering the possibility that any write to the card would invalidate the cache. It is the easiest implementable option. All you have to do is delete the file from the cache for put-data, update-binary, etc. operations.

I agree, that invalidating the cache on write would be a good way of handling this issue. However, sc_update_binary/sc_write_binary are directly called from the card specific the implmentations in src/pkcs15init without using some generic layer of writing PKCS#15 files. For reading files we have sc_pkcs15_read_file (where caching is handled transparently), but there is no such equivalent for writing files.

Unfortunately, it looks like some bigger refactoring would be required to update/invalidate the file caching when writing files to the card. As simple workaround, I've changed this PR to disable file caching by default when running pkcs15-init

I see that this time it crashed on keygen.... (public key can not be exported from card)... I'll guess, it would crash during the unwrap operation too.

I'm afraid that the current cache implementation will not allow us to use it safely. I will still be looking for some solution ..

Thank you. I'll convert this PR into a draft for now...

@popovec I don't quite get the issue why oseid is failing, could you have a look?

I don't have a final solution, but at least a hint:

I have applied this PR to master (fa2eab8). If cache is cleared (pkcs15-tool --clear-cache) after commands:

• pkcs15-init --store-private-key
• pkcs15-init --store-certificate
• pkcs15-init --generate-key
• pkcs15-init --store-secret-key
• pkcs11-tool --unwrap

the OsEID test is fine.

I looked at the cache implementation. Since any write to card does not pass through the cache, respectively, the cache is not invalidated if there was a write to the card, this implementation can only work if the card is in read only mode. This explains the failure of the OsEID tests, especially in cases where the previous command modified the contents of the card.

If the file cache is enabled, some files are cached on computer. Then, if the card is modified on another computer (even without/with cache enabled), the cache on first computer is also not updated.

The only solution that ensures the consistency of the operation when using the file cache is to use some flag (on the card) that will change when the card is updated. This flag must always be checked before using a file from the cache, and if it is invalid, the cache must be invalidated.

Some of the cards contain a counter that is incremented with each write to the card. The use of such a counter to ensure the consistency of the contents of the card and the cache is sufficient. MyEID card has such a counter. I don't know if similar information is provided by other cards supported in OpenSC. (OsEID does not have this counter implemented - if necessary, I will write this code.)

If similar information is available from other cards supported in OpenSC, I will write a PR that will invalidate the cache based on this information. If a card does not provide this information, file caching should be disabled for that card.

The file cache implemented in this way will be a bit slower than the current implementation, because before each use of a file from the cache, one APDU will have to be used to verify the state of the change counter.

I agree with @popovec
I also think the card driver should be able to turn this off especially if the card does not have some update counter. Even if card has update counter, the previous update counter would have to be cached to do a compare.

Newer cards are much faster. It is not clear how fast are the cards listed in #2444. Tokens should be must fasted if they can eliminate the limitations of contact protocols, and power restrictions.

Thanks for the feedback and i think that speaking strictly technical, you're right with your concerns. However, I still believe that

1. 99% of all tokens used with OpenSC do have a static content
2. Most tokens are slow and will be slow for the next decade

Anyway, I agree that we should try to avoid any caching conflicts in OpenSC by default. I've modified this PR to enable file caching only for the cards we cannot modify within OpenSC. If you think this list is not restrictive enough, please let me know and I'll remove more entries.

@popovec versioning of the card's file cache is done using the card's meta data in EF.TokenInfo. This file contains a date that is appended to the file name (p15card->tokeninfo->last_update, see sc_pkcs15_get_lastupdate). So if you want to support your file modification counter from the card, you need to modify your PKCS#15 emulator so that this date is adjusted once that counter increments. This tells the pkcs#15 file cache that it needs to fetch the file(s) again from the card.

I am wondering if this should be a hardcoded list or if this should be a property of the card driver, that can be even dynamically changed based on the content of the card. For example, the cardos < v5 cards can be modified from within OpenSC, but v5 can not as we were not able to obtain any documentation.

The limitation to modification by opensc only can also be a limiting for example for yubikeys with PIV applets, which can be modified by other tools and where checking of some counter/tokeninfo or something would be handy, but I dont know if there is something in the PIV specification that could be used to detect changes though.

So aside of the comment inline, this looks like a step in the good direction.

The problem is that the timestamp (in EF.tokeninfo) is not updated atomically. Maybe we have a new version of the file written on the card, but EF.tokeninfo is not yet updated ... and therefore the cache will provide the old version of the file.

I prepared a patch for both opensc and oseid simulator, which uses change_counter. With the use of change_counter the file cache works without problems.

OpenSC patch:
https://github.com/popovec/oseid/blob/change_counter_test/experimental/opensc_update_counter.diff

OsEID patch:
https://github.com/popovec/oseid/compare/change_counter_test

Experimental run:
https://github.com/popovec/oseid/actions/runs/3089712296
(logs in Artefacts).

Comments are welcome.

The problem is that the timestamp (in EF.tokeninfo) is not updated atomically. Maybe we have a new version of the file written on the card, but EF.tokeninfo is not yet updated ... and therefore the cache will provide the old version of the file.

I prepared a patch for both opensc and oseid simulator, which uses change_counter. With the use of change_counter the file cache works without problems.

I also thought about this limitation and - of course - you could do some on-the-fly magic, catching special FIDs when being called with select and returning prepared file contents with read_binary afterwards (I think sc-hsm and piv are emulating such files). However, I think that is somewhat obscure.

Instead of using a card driver callback as in your suggestion, I propose to use sc_card_ctl with the new value SC_CARDCTL_GET_LASTUPDATE. For some reason we're only using sc_card_ctl from the PKCS#15 level instead of directly calling some driver call back. You can compare this approach with the method of getting the serial number in sc_pkcs15_bind_internal, i.e. first parse EF.TokenInfo if possible, then try sc_card_ctl. I think it should be enough if the ctl just returns a char * representing the date. The date is just a postfix of the cache file name, so it is possible to directly use the value of your counter here (without mapping the counter to a certain date/time format).

I am wondering if this should be a hardcoded list or if this should be a property of the card driver, that can be even dynamically changed based on the content of the card.

we can use defensive defaults, here (e.g. excluding cardos and piv in the list). for a more flexible approach we should use Peter's suggestion for checking the date of the last change dynamically.

Thanks for the hint about using sc_card_ctl. I would not like to mix the technical value "change counter" with the software-generated date in EF.Tokeninfo. In addition, the value in EF.Tokeninfo must not be updated at all (see profile setting do-last-update = no; for the MyEID card). For the above reason, I preferred to use a new value called SC_CARDCTL_GET_CHANGE_COUNTER for the sc_card_ctl call.

Since we only need the information from the change_counter for the file cache for now, I made changes only in the generation of the file name for the cache:

master...popovec:OpenSC:change_counter

A test run including a debug log is available:

https://github.com/popovec/oseid/actions/runs/3112393116

The implementation of a change counter is specific to your card and may be different for others whereas we already have the last update information from the upper PKCS#15 layer. I don't like introducing new concepts for something we already have, because this raises complexity, which is bad for basically everything in the long run. That's why I would prefer a mapping of the "last update" from the PKCS#15 level to the driver level. In my view, this is less complex, because it only changes where it is implemented, but the concept stays the same.

So far, I assumed that myeid doesn't encode the "last update", which is why you want to look at the change counter instead. However, looking into your driver's code (pkcs15init/pkcs15-myeid.c), I can see that the "last update" will actually written to your card with sc_pkcs15init_unbind. So when modifying the card via PKCS#11, I wonder why the "last update" isn't adjusted accordingly (which would then also fix the caching problem)...

Could it be that we forgot to call sc_pkcs15init_update_lastupdate() somewhere in the PKCS#11 layer?

Could it be that we forgot to call sc_pkcs15init_update_lastupdate() somewhere in the PKCS#11 layer?

I will look at the relevant code, maybe I manage to find another solution (by correcting the current code).

Can we get information about other cards supported in opensc, do they support "change_counter" information? If so, consider this information authoritative for the file cache. If not, I'll assume that mapping change_counter to last_update (from EF.Tokeninfo) will be an easier - cleaner solution (specially, we can map change_counter as "subseconds" information to the last update from EF.Tokenifo). But it will cost us more APDU transfers...

In sc_pkcs15_get_lastupdate() is implemented the caching of information from the EF.Tokeninfo file. Even if I block this code, the file cache does not work properly:

index dac6808a..b682fd1e 100644
--- a/src/libopensc/pkcs15.c
+++ b/src/libopensc/pkcs15.c
@@ -533,8 +533,10 @@ sc_pkcs15_get_lastupdate(struct sc_pkcs15_card *p15card)
        int r, content_len;
        size_t size;
 
-       if (p15card->tokeninfo->last_update.gtime)
-               goto done;
+       if (p15card->tokeninfo->last_update.gtime) {
+               free(p15card->tokeninfo->last_update.gtime);
+               p15card->tokeninfo->last_update.gtime = NULL;
+       }
 
        if (!p15card->tokeninfo->last_update.path.len)
                return NULL;
@@ -567,7 +569,7 @@ sc_pkcs15_get_lastupdate(struct sc_pkcs15_card *p15card)
        p15card->tokeninfo->last_update.gtime = strdup((char *)last_update);
        if (!p15card->tokeninfo->last_update.gtime)
                return NULL;
-done:
+
        sc_log(ctx, "lastUpdate.gtime '%s'", p15card->tokeninfo->last_update.gtime);
        return p15card->tokeninfo->last_update.gtime;
 }

I tried to use update_counter instead of information from EF.tokeninfo, but keep the current cache for p15card->tokeninfo->last_update.gtime.

index dac6808a..1a684f7a 100644
--- a/src/libopensc/pkcs15.c
+++ b/src/libopensc/pkcs15.c
@@ -536,6 +536,9 @@ sc_pkcs15_get_lastupdate(struct sc_pkcs15_card *p15card)
        if (p15card->tokeninfo->last_update.gtime)
                goto done;
 
+       if (SC_SUCCESS == sc_card_ctl(p15card->card, SC_CARDCTL_GET_CHANGE_COUNTER, last_update))
+               goto done_change_counter;
+
        if (!p15card->tokeninfo->last_update.path.len)
                return NULL;
 
@@ -564,6 +567,7 @@ sc_pkcs15_get_lastupdate(struct sc_pkcs15_card *p15card)
        if (r < 0)
                return NULL;
 
+done_change_counter:
        p15card->tokeninfo->last_update.gtime = strdup((char *)last_update);
        if (!p15card->tokeninfo->last_update.gtime)
                return NULL;

The file cache is also defective in this case.

I can modify sc_pkcs15_get_lastupdate() so that it always reads the change_counter value from the card. If the card driver does not provide this value, the function behaves as before. If the information from the change_counter is available, it will be concatenated to the EF.Tokeninfo information or to the information in p15card->tokeninfo->last_update.gtime. This value would be used to generate the file name in the file cache.

However, the sc_pkcs15_get_lastupdate() function must also be modified in the case that change_counter is available, but we do not have information from EF.Tokeninfo (in that case, the current return value is NULL).

I'm afraid this will be much more complicated than prioritizing the update_counter information directly for the file cache name (as I mentioned in the previous solution).

Here is also information about how much time it takes to execute the command: pkcs15-tool -D (MyEID 4.0.1 card, content 2x PIN, 3x public and private key) needs about 2.4 seconds (without file cache). Current file cache implementation (with cache on EF.Tokeninfo) 0.45 seconds, file cache using update_counter 0.65 seconds.

Thank you for having a look into this @popovec ! Do I read it correctly that there is no way to update cache except for manually deleting the files right now?

The problem is that we cannot determine when the cache should be invalidated. As mentioned above, the card driver can change something on the card without notifying us in any way (at the pkcs#15 layer level). Preliminarily, let's assume that such changes do not happen ... the file cache can work without problems under certain conditions.

File cache currently uses file versioning based on information from EF.Tokeninfo. This information has a resolution of one second. We have some limitations from this.

Cards initialized with opensc must have "do-last-update" set to "yes" (in the pkcs#15 profile used to initialize the card).
Initialization using opensc is possible only with the file cache turned off (Ef.Tokeninfo resolution is not sufficient and the gtime information from EF.Tokeninfo is also cached).

Also modification of the card (generation/import of keys, update of certificates, etc.) via opensc is possible, but with the file cache disabled. Any change to the card contents made outside of opensc must guarantee a properly updated EF.Tokeninfo.

Many cards cannot be initialized/updated with opensc (read only cards). File cache can be enabled for these cards. This PR is aimed at this case, so I don't think there is anything preventing this PR from being used. (However, I don't know enough about all the supported cards to say which card will later cause a problem after turning on the file cache, specifically I can't say if any other modification of the card outside of opensc will update the EF.Tokeninfo correctly and thus not break the current version of the files).

In the future, it will be possible to enable file caching for other (read write) cards as well. If the card (card driver) provides change counter information, it is advisable to change the versioning of the cache files according to this information. In this case, the file cache will also be fully functional.

I would prefer to change the generate_cache_filename() function without changing the sc_pkcs15_get_lastupdate() function, which itself uses a cache for gtime information (from EF.Tokeninfo).

An example of changing the name of the cache file is in the patch:08b1ca6

IMHO, we should not enable caching by default.

I've rebased the changes onto master and fixed the merge conflicts. I've also noticed a syntax error in the documentation, which is present in master.

Looking into your suggested changes, @popovec , I think that simply using the change counter in the file name (i.e. 08b1ca6) is the best way to integrate this for dynamic cards. When you have the time to make a PR, maybe you also want to consider just appending your change counter to the last update date instead of replacing it.

Can we get information about other cards supported in opensc, do they support "change_counter" information?

I'm not aware of any other card implementing this. However, the MS Minidriver takes exactly this approach at the middleware level, so at least someone else had a similar idea before...

A cache enabled by default starts to make trouble:

https://support.nitrokey.com/t/hsm2-cant-figure-out-how-to-properly-wipe-and-reinitialize-device-seems-to-generate-invalid-signatures/4688
https://support.nitrokey.com/t/the-same-key-is-regenerated-each-time/4713

I guess we should not ship with cache enabled by default.

A cache enabled by default starts to make trouble

We've been there already. The idea is to enable caching only for static cards (e.g. not for sc-hsm) by default. However, a dynamic mechanism has been suggested to allow this for the other cards as well

maybe you also want to consider just appending your change counter to the last update date instead of replacing it.

Here is a proposal for a change counter implementation including this PR:
https://github.com/popovec/OpenSC/tree/default_caching_test
(https://github.com/popovec/OpenSC/actions/runs/390178105)

filename is now in this format:
00000000000000000001_20230112120253Z_11352_50154401
(card serial, last_update, change_counter, file path)

I think we can merge, if everyone agrees that we only enable file caching for the static cards with this PR (the list given here):
https://github.com/OpenSC/OpenSC/pull/2501/files#diff-005dde6d43739a09698893ee783a2dcb11271a587ee079454c05ac9ddbfc001cR1222-R1243

I agree, static cards are solved by this PR. I will prepare a separate PR for the MyEID card.

I am ok with the current version (after updating the HTML mentioned in the previous comment). Ideal solution would be to have more fine-grained selection to allow file caching for NIST PIV cards, but not allow it for the Yubikeys by default, but that would complicate stuff a lot.