Fedora/RHEL pkcs11-helper RPMs break gnupg-pkcs11-scd integration with gnupg

[antimeme]

This is not a problem with gnupg-pkcs11-scd itself, but a warning for anyone attempting to use PKCS#11 keys with GnuPG on a Fedora or RHEL compatible system. If you attempt this DO NOT USE the pkcs11-helper or pkcs11-helper-devel RPMs provided by Fedora or Fedora EPEL to build gnupg-pkcs11-scd. At present it appears there are no RPM packages for gnupg-pkcs11-scd for Fedora or RHEL so you must build that package regardless. But if you depend on pkcs11-helper RPMs it will change the URIs exposed in a way that will break integration with GNU Privacy Guard. Compiling pkcs11-helper and gnupg-pkcs11-scd from upstream solves the problem, as does using a non-RedHat distribution like Debian.

I've filed a bug against pkcs11-helper with RedHat explaining this issue:

https://bugzilla.redhat.com/show_bug.cgi?id=2298882

Here's what happens after configuring a PKCS#11 provider and attempting to import a PGP key:

$ gpg --expert --full-generate-key
[...]
Your selection? 14
Serial number of the card: D2760001240111503131AD4306431111
Available keys:
   (1) 258DAF945486847792A1AC4F9E69487B7F6EF2A2 pkcs11:model=;token=loadshared%20accelerator;manufacturer=nCipher%20Corp.%20Ltd;serial=;id=%25%8d%af%94T%86%84w%92%a1%acO%9eiH%7b%7fn%f2%a2 (null)
[...]
gpg: [internal]:0: invalid algorithm

Note the (null) at the end of the key line.

Here's the exact same configuration after rpm -e pkcs11-helper pkcs11-helper-devel followed by compiling pkcs11-helper and recompiling gnupg-pkcs11-scd:

$ gpg --expert --full-generate-key
[...]
Your selection? 14
Serial number of the card: D2760001240111503131AD4306431111
Available keys:
   (1) 258DAF945486847792A1AC4F9E69487B7F6EF2A2 nCipher\x20Corp\x2E\x20Ltd///loadshared\x20accelerator/258DAF945486847792A1AC4F9E69487B7F6EF2A2 rsa2048

Now the end of the line has rsa2048 instead of (null) for the last field.

After answering questions about validity, user name and email address this leads to a successful import. I'm able to sign and verify files using the corresponding key pair. No changes were made either to the configuration or to gnupg-pkcs11-scd sources to get this result.

If you're trying to use GnuPG with PKCS#11 keys DO NOT USE the pkcs11-helper or pkcs11-helper-devel RPMs provided by Fedora or Fedora EPEL. Compile the source code from here instead:

https://github.com/OpenSC/pkcs11-helper

[saper]

The links are:

https://bugzilla.redhat.com/show_bug.cgi?id=2298882

https://github.com/OpenSC/pkcs11-helper

[saper]

EPEL has gnupg-pkcs11-scd built without patches, but they do patch https://src.fedoraproject.org/rpms/pkcs11-helper/blob/rawhide/f/pkcs11-helper-rfc7512.patch indeed (which seems to be related to https://github.com/OpenSC/pkcs11-helper/pull/4)

Does the EPEL version break as well?

What happens if you use p11-kit-proxy.so as your PKCS#11 driver in front of the nCrypt one?

[dwmw2]

Is there a problem with the standard URIs generated by pkcs11-helper, or is it just that they're being fed to something which is still expecting some legacy format instead of the RFC7512 standard?

[saper]

I think gnupg does not care what it receives. What worries me that gnupg shows rsa2024 algorithm without the patch and that it reports '(none)'

@antimeme can you try the following:

make sure you have the xxd program that comes with vim-common on Enterprise Linux

$ rpm -qf `which xxd`
vim-common-8.2.2637-20.el9_1.x86_64

add the following lines to your gpg-agent.conf and restart it

debug 0xffff
log-file /tmp/agent.log

(please be aware that /tmp/agent.log will contain sensitive information, like your PIN and some data from the smartcard which you might not want to share)

After selecting option 14 in GPG, there should be SCD READKEY --info command somewhere with the keygrip and the ID returned by the patched pkcs11-helper:

$ grep READKEY /tmp/agent.log | head -1
2024-09-27 22:22:01 gpg-agent[8926] DBG: chan_8 <- SCD READKEY --info -- SoftHSM\x20project/SoftHSM\x20v2/612af22c9b89c492/GPGTEST/82A1CFB4E839DA53E47DFC1322C4C7956DE79DE5

Once you get that command out, can you try to grab the full output of it with a hexdump like this:

$ cat /tmp/cmd
gpg-connect-agent 'SCD READKEY --info -- SoftHSM\x20project/SoftHSM\x20v2/612af22c9b89c492/GPGTEST/82A1CFB4E839DA53E47DFC1322C4C7956DE79DE5' /bye | xxd
$ sh /tmp/cmd 
00000000: 5320 4b45 5950 4149 5249 4e46 4f20 4443  S KEYPAIRINFO DC
00000010: 4437 4632 3844 4431 3834 3042 3134 4535  D7F28DD1840B14E5
00000020: 3031 4331 3443 4236 3546 3733 3037 3746  01C14CB65F73077F
00000030: 3438 3139 4431 2053 6f66 7448 534d 5c78  4819D1 SoftHSM\x
00000040: 3230 7072 6f6a 6563 742f 536f 6674 4853  20project/SoftHS
00000050: 4d5c 7832 3076 322f 3631 3261 6632 3263  M\x20v2/612af22c
00000060: 3962 3839 6334 3932 2f47 5047 5445 5354  9b89c492/GPGTEST
00000070: 2f38 3241 3143 4642 3445 3833 3944 4135  /82A1CFB4E839DA5
00000080: 3345 3437 4446 4331 3332 3243 3443 3739  3E47DFC1322C4C79
00000090: 3536 4445 3739 4445 350a 4420 2831 303a  56DE79DE5.D (10:
000000a0: 7075 626c 6963 2d6b 6579 2833 3a72 7361  public-key(3:rsa
000000b0: 2831 3a6e 3235 373a 00b7 f209 a3fa 5d27  (1:n257:......]'
000000c0: 4e4f 4898 7729 241a e598 1306 7efe 6177  NOH.w)$.....~.aw
000000d0: ec3c abff 62ae 08d3 05fe ed87 3be5 3368  .<..b.......;.3h
000000e0: 6119 6c83 8eda 28fc 7174 5159 a43b 4ccf  a.l...(.qtQY.;L.
000000f0: 52e5 3208 1ed9 d38a f3e6 d78b 3ebd d2a1  R.2.........>...
00000100: 8288 cf36 8bef f699 bfd4 90f7 0845 8c12  ...6.........E..
00000110: f187 b7ef bda1 a490 6868 f9a6 8aeb b1e1  ........hh......
00000120: 3fd1 11cf a529 125f cd72 3fba a191 5bbb  ?....)._.r?...[.
00000130: 5dd1 3391 95f1 4368 7b2f e5d4 d2bc fdef  ].3...Ch{/......
00000140: c4a1 a6eb dbcc feda fbee 2942 525b 29da  ..........)BR[).
00000150: 5770 223c e8b3 5888 c6e3 f760 0848 7b34  Wp"<..X....`.H{4
00000160: 8765 290b 8f47 6236 5601 7cb7 3816 d1ed  .e)..Gb6V.|.8...
00000170: 043c 85d0 912a 982c 4232 e1b9 da7d d74b  .<...*.,B2...}.K
00000180: 1f96 8454 ca1a d9f8 c32a 36e0 1ab7 45ef  ...T.....*6...E.
00000190: dbb6 9014 c745 c6d5 5bd1 1478 9c7f 2df1  .....E..[..x..-.
000001a0: 549c ac08 23bc 8b34 ea01 708c b246 9ff2  T...#..4..p..F..
000001b0: e7d2 8c29 045c 86b3 e129 2831 3a65 333a  ...).\...)(1:e3:
000001c0: 0100 0129 2929 0a4f 4b0a                 ...))).OK.

[saper]

I have started playing with strange encoding of the values and it turns out, when something strange is received, gnupg-pkcs11-scd may simply crash:

Sep 28 02:13:00 radziecki kernel: pid 24787 (gnupg-pkcs11-scd), jid 0, uid 1002: exited on signal 6 (no core dump - too large)

2024-09-28 02:13:00 gpg-agent[24786] DBG: chan_8 <- SCD READKEY --info -- SoftHSM%20project/SoftHSM%20v2/fe67bb79d35d2535/loadshared%20accelerator/<A5><A5><A5><A5><A5><A5><A5><A5><A5><A5>
<A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5>
<A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5>
2024-09-28 02:13:00 gpg-agent[24786] DBG: chan_9 -> READKEY --info -- SoftHSM%20project/SoftHSM%20v2/fe67bb79d35d2535/loadshared%20accelerator/<A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5>
<A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5>
<A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5><A5>
2024-09-28 02:13:00 gpg-agent[24786] DBG: chan_9 <- [eof]
2024-09-28 02:13:00 gpg-agent[24786] DBG: chan_8 -> ERR 67125247 End of file <GPG Agent>
2024-09-28 02:13:00 gpg-agent[24786] daemon /usr/local/bin/gnupg-pkcs11-scd killed by signal 6
2024-09-28 02:13:00 gpg-agent[24786] DBG: agent_flush_cache (pincache only)
2024-09-28 02:13:00 gpg-agent[24786] DBG: chan_9 -> BYE
2024-09-28 02:13:01 gpg-agent[24786] DBG: chan_8 <- [eof]

but gpg2 does not notice that really, and both scd and gpg-agent are quickly restarted:

Available keys:
   (1) 63F8859168EC09711B4C16A163198FA04ECFED6F SoftHSM%20project/SoftHSM%20v2/fe67bb79d35d2535/loadshared%20accelerator/¥¥¥¥¥¥¥¥¥¥¥¥¥¥¥¥¥¥¥¥¥¥¥¥¥¥¥¥¥¥¥¥¥¥¥¥¥¥¥¥¥¥¥¥¥¥¥¥¥¥¥¥¥¥¥ (null)
Your selection? 

Stacktrace:

(gdb) bt
#0  thr_kill () at thr_kill.S:4
#1  0x0000000825f60714 in __raise (s=s@entry=6) at /usr/src/lib/libc/gen/raise.c:48
#2  0x0000000826013319 in abort () at /usr/src/lib/libc/stdlib/abort.c:61
#3  0x0000000825f44091 in __assert (func=<optimized out>, file=<optimized out>, 
    line=<optimized out>, failedexpr=<optimized out>) at /usr/src/lib/libc/gen/assert.c:47
#4  0x0000000823e6ff26 in _pkcs11h_mem_malloc (p=0x3d4a17088e08, s=0) at pkcs11h-mem.c:64
#5  0x0000000823e70112 in _pkcs11h_mem_duplicate (dest=0x3d4a17088e08, 
    p_dest_size=0x3d4a17088e10, src=0x3d4a17026aa0, mem_size=0) at pkcs11h-mem.c:126
#6  0x0000000823e76dab in pkcs11h_certificate_duplicateCertificateId (to=0x3d4a17064200, 
    from=0x3d4a1708a800) at pkcs11h-certificate.c:1199
#7  0x0000000823e7a1db in pkcs11h_certificate_create (certificate_id=0x3d4a1708a800, 
    user_data=0x3d4a17057000, mask_prompt=7, pin_cache_period=-1, p_certificate=0x820d92710)
    at pkcs11h-certificate.c:2025
#8  0x000000000020a68b in get_cert_blob (ctx=0x3d4a17057000, cert_id=0x3d4a1708a800, 
    p_blob=0x820d92758, p_blob_size=0x820d92750) at command.c:85
#9  0x0000000000209aa6 in get_cert_sexp (ctx=0x3d4a17057000, cert_id=0x3d4a1708a800, 
    p_sexp=0x820d927f0) at command.c:157
#10 0x000000000020a8de in cmd_readkey (ctx=0x3d4a17057000, 
    line=0x3d4a17057158 "--info -- SoftHSM%20project/SoftHSM%20v2/fe67bb79d35d2535/loadshared%20accelerator/", '\245' <repeats 55 times>) at command.c:893
#11 0x0000000821c7cd99 in ?? () from /usr/local/lib/libassuan.so.0
#12 0x0000000821c7bf88 in assuan_process () from /usr/local/lib/libassuan.so.0
#13 0x00000000002083fd in command_handler (global=0x820d92ef0, fd=-1) at scdaemon.c:265
#14 0x0000000000206e88 in main (argc=2, argv=0x820d93258) at scdaemon.c:1407

#4  0x0000000823e6ff26 in _pkcs11h_mem_malloc (p=0x3d4a17088e08, s=0) at pkcs11h-mem.c:64
64      _PKCS11H_ASSERT (s!=0);

(this is gnupg-pkcs11-scd 0.10.0 linked with pkcs11-helper 1.29.0 + my experiments)

[antimeme]

EPEL has gnupg-pkcs11-scd

Interesting! I was not able to find this back in July, but I see it now and the package creation date seems to go back to May. Either I messed up dnf search in July or the package hadn't been published yet. Either way, I just tried this again and still get the (null) result described above with the EPEL gnupg-pkcs11-scd package.

Your selection? 14
Serial number of the card: D27600012401115031319DE9939B1111
Available keys:
   (1) 9A986AA0B6CE0BAE5BE058DCEF13F742911DB593 pkcs11:model=;token=accelerator;manufacturer=nCipher%20Corp.%20Ltd;serial=A9DB-D03C-115F;id=%9a%98j%a0%b6%ce%0b%ae%5b%e0X%dc%ef%13%f7B%91%1d%b5%93 (null)
Your selection? 

What happens if you use p11-kit-proxy.so as your PKCS#11 driver in front of the nCrypt one?

This is something I'd have to tinker with to set up properly, so for the moment I don't know.

Here is the agent.log file from the results above with debug 0xffff set in gpg-agent.conf (note that I did explicitly request a restart using RELOADAGENT and SCD LEARN which I imagine is the reason for SIGHUP). I see no evidence of a crash, but the entire file is only 30 lines so I'm including it in full. This is a development system with no sensitive data.

2024-09-27 22:32:10 gpg-agent[961246] DBG: chan_4 -> OK Pleased to meet you
2024-09-27 22:32:10 gpg-agent[961246] DBG: chan_4 <- RELOADAGENT
2024-09-27 22:32:10 gpg-agent[961246] SIGHUP received - re-reading configuration and flushing cache
2024-09-27 22:32:10 gpg-agent[961246] DBG: agent_flush_cache
2024-09-27 22:32:10 gpg-agent[961246] enabled debug flags: mpi crypto memory cache memstat hashing ipc
2024-09-27 22:32:10 gpg-agent[961246] DBG: chan_4 -> OK
2024-09-27 22:32:10 gpg-agent[961246] DBG: chan_4 <- SCD LEARN
2024-09-27 22:32:10 gpg-agent[961246] no running SCdaemon - starting it
2024-09-27 22:32:11 gpg-agent[961246] DBG: chan_6 <- OK PKCS#11 smart-card server for GnuPG ready
2024-09-27 22:32:11 gpg-agent[961246] DBG: first connection to SCdaemon established
2024-09-27 22:32:11 gpg-agent[961246] DBG: chan_6 -> GETINFO socket_name
2024-09-27 22:32:11 gpg-agent[961246] DBG: chan_6 <- D /tmp/gnupg-pkcs11-scd.lf7sqF/agent.S
2024-09-27 22:32:11 gpg-agent[961246] DBG: chan_6 <- OK
2024-09-27 22:32:11 gpg-agent[961246] DBG: additional connections at '/tmp/gnupg-pkcs11-scd.lf7sqF/agent.S'
2024-09-27 22:32:11 gpg-agent[961246] DBG: chan_6 -> LEARN
2024-09-27 22:32:11 gpg-agent[961246] DBG: chan_6 <- S SERIALNO D27600012401115031319DE9939B1111
2024-09-27 22:32:11 gpg-agent[961246] DBG: chan_4 -> S SERIALNO D27600012401115031319DE9939B1111
2024-09-27 22:32:11 gpg-agent[961246] DBG: chan_6 <- S APPTYPE PKCS11
2024-09-27 22:32:11 gpg-agent[961246] DBG: chan_4 -> S APPTYPE PKCS11
2024-09-27 22:32:11 gpg-agent[961246] DBG: chan_6 <- S KEY-FRIEDNLY 9A986AA0B6CE0BAE5BE058DCEF13F742911DB593 /C=AU/ST=Some-State/O=Internet Widgits Pty Ltd/CN=server.example.com/emailAddress=username@example.com on accelerator
2024-09-27 22:32:11 gpg-agent[961246] DBG: chan_4 -> S KEY-FRIEDNLY 9A986AA0B6CE0BAE5BE058DCEF13F742911DB593 /C=AU/ST=Some-State/O=Internet Widgits Pty Ltd/CN=server.example.com/emailAddress=username@example.com on accelerator
2024-09-27 22:32:11 gpg-agent[961246] DBG: chan_6 <- S CERTINFO 101 pkcs11:model=;token=accelerator;manufacturer=nCipher%20Corp.%20Ltd;serial=A9DB-D03C-115F;id=%9a%98j%a0%b6%ce%0b%ae%5b%e0X%dc%ef%13%f7B%91%1d%b5%93
2024-09-27 22:32:11 gpg-agent[961246] DBG: chan_4 -> S CERTINFO 101 pkcs11:model=;token=accelerator;manufacturer=nCipher%20Corp.%20Ltd;serial=A9DB-D03C-115F;id=%9a%98j%a0%b6%ce%0b%ae%5b%e0X%dc%ef%13%f7B%91%1d%b5%93
2024-09-27 22:32:11 gpg-agent[961246] DBG: chan_6 <- S KEYPAIRINFO 9A986AA0B6CE0BAE5BE058DCEF13F742911DB593 pkcs11:model=;token=accelerator;manufacturer=nCipher%20Corp.%20Ltd;serial=A9DB-D03C-115F;id=%9a%98j%a0%b6%ce%0b%ae%5b%e0X%dc%ef%13%f7B%91%1d%b5%93
2024-09-27 22:32:11 gpg-agent[961246] DBG: chan_4 -> S KEYPAIRINFO 9A986AA0B6CE0BAE5BE058DCEF13F742911DB593 pkcs11:model=;token=accelerator;manufacturer=nCipher%20Corp.%20Ltd;serial=A9DB-D03C-115F;id=%9a%98j%a0%b6%ce%0b%ae%5b%e0X%dc%ef%13%f7B%91%1d%b5%93
2024-09-27 22:32:11 gpg-agent[961246] DBG: chan_6 <- OK
2024-09-27 22:32:11 gpg-agent[961246] DBG: chan_4 -> OK
2024-09-27 22:32:11 gpg-agent[961246] DBG: chan_4 <- [eof]
2024-09-27 22:32:11 gpg-agent[961246] DBG: chan_6 -> RESTART
2024-09-27 22:32:11 gpg-agent[961246] DBG: chan_6 <- OK

[antimeme]

Here is the output of the READKEY command you requested:

$ gpg-connect-agent 'SCD READKEY --info -- 9A986AA0B6CE0BAE5BE058DCEF13F742911DB593' < /dev/null | xxd
00000000: 5320 4b45 5950 4149 5249 4e46 4f20 3941  S KEYPAIRINFO 9A
00000010: 3938 3641 4130 4236 4345 3042 4145 3542  986AA0B6CE0BAE5B
00000020: 4530 3538 4443 4546 3133 4637 3432 3931  E058DCEF13F74291
00000030: 3144 4235 3933 2070 6b63 7331 313a 6d6f  1DB593 pkcs11:mo
00000040: 6465 6c3d 3b74 6f6b 656e 3d61 6363 656c  del=;token=accel
00000050: 6572 6174 6f72 3b6d 616e 7566 6163 7475  erator;manufactu
00000060: 7265 723d 6e43 6970 6865 7225 3230 436f  rer=nCipher%20Co
00000070: 7270 2e25 3230 4c74 643b 7365 7269 616c  rp.%20Ltd;serial
00000080: 3d41 3944 422d 4430 3343 2d31 3135 463b  =A9DB-D03C-115F;
00000090: 6964 3d25 3961 2539 386a 2561 3025 6236  id=%9a%98j%a0%b6
000000a0: 2563 6525 3062 2561 6525 3562 2565 3058  %ce%0b%ae%5b%e0X
000000b0: 2564 6325 6566 2531 3325 6637 4225 3931  %dc%ef%13%f7B%91
000000c0: 2531 6425 6235 2539 330a 4420 2831 303a  %1d%b5%93.D (10:
000000d0: 7075 626c 6963 2d6b 6579 2833 3a72 7361  public-key(3:rsa
000000e0: 2831 3a6e 3235 373a 00b0 8152 4c98 c170  (1:n257:...RL..p
000000f0: 05ca 0626 fbbe 2919 6302 f7ee dc52 9f28  ...&..).c....R.(
00000100: 3c26 b3cc e279 2f22 f2c6 3ae4 04de bf98  <&...y/"..:.....
00000110: 9f95 0c30 2ab5 89b1 2532 3569 ca23 ac39  ...0*...%25i.#.9
00000120: b3a6 31fb e489 d425 3235 11ad 51d3 7eac  ..1....%25..Q.~.
00000130: b832 93b4 7731 5134 aafc cf87 41af 2e7c  .2..w1Q4....A..|
00000140: 8ddb 9e53 2e61 7299 cac2 3866 3c6d 4dbe  ...S.ar...8f<mM.
00000150: fb93 6edd 06a0 cac5 e291 2530 4410 9d13  ..n.......%0D...
00000160: f824 e3d5 befb e472 8543 a3d1 c46c c949  .$.....r.C...l.I
00000170: 4067 e64d 6ddf a737 5f05 af64 3751 35d8  @g.Mm..7_..d7Q5.
00000180: fd85 40b7 6b2a 8fba f611 899d 490e c8ec  ..@.k*......I...
00000190: e6d0 ad44 17a8 e1ac 0ee9 badd d2ad 2e20  ...D........... 
000001a0: 72e9 e30f d2fc 6e45 749f adb3 894d d1d3  r.....nEt....M..
000001b0: 2136 79ca 436b d1c1 3357 2ea4 9d09 4bca  !6y.Ck..3W....K.
000001c0: 1b2f 5622 2a4e 1940 18e0 69c8 8a7e 61bc  ./V"*N.@..i..~a.
000001d0: b226 3c45 0b07 f3f4 7174 a362 69ad c910  .&<E....qt.bi...
000001e0: 52d7 0698 34c4 ebd5 4a84 d3f6 c323 5d29  R...4...J....#])
000001f0: 2831 3a65 333a 0100 0129 2929 0a4f 4b0a  (1:e3:...))).OK.

[saper]

Thank you for coming back (I thought you might have given up on this already).

I am interested in the actual SCD READKEY output - as executed. But looks like we don't have it in the log.

I think the problem is in the way you reproduce it. You might be starting two different agents, as your agent logfile contains the output only from the echo -e 'RELOADAGENT\nSCD LEARN' | gpg-agent --server gpg-connect-agent command, not from gpg.

I also have log-file /tmp/sc-gpguser.log in my .gnupg/gnupg-pkcs11-scd.conf just in case.

I do something like this:

gpg-connect-agent killagent /bye
rm -f /tmp/agent.log
rm -f /tmp/sc-gpguser.log
gpg-connect-agent 'scd getinfo pid' /bye
# I usually attach the debugger here
gpg2 --expert --full-generate-key

Maybe we should sync the reproducer to some gist to make sure we are all on the same page.

Again, let's see what gpg is doing. After SCD LEARN there should be a series of SCD GETATTR $AUTHKEYID etc. and after this SCD READKEY

Enterprise Linux derivatives like to hide the crashes. (I debug on FreeBSD right now)

Maybe something like sysctl -w kernel.core_pattern="/tmp/%e_core.%p" as root combined with making sure ulimit -c is unlimited can help.

[antimeme]

I feel I should clarify that this problem is solved for me: the solution is to use upstream sources, either by using a non-RHEL distribution like Debian or compiling the pkcs11-helper and gnupg-pkcs11-scd packages. I gather that some people want RFC 7512 URIs for use with other applications, but upstream pkcs11-helper just doesn't do that. Some people must like the patched version or it wouldn't be shipped but the patch breaks gnupg integration with PKCS#11 (at least with nShield HSMs -- I haven't tested other PKCS#11 implementations).

It's not clear how to make the RFC 7512 patch acceptable to the pkcs11-helper maintainers, but if it were up to me I'd require concurrent changes to gnupg-pkcs11-scd so that it understands the new URI format and presents something gnupg can understand. I'm willing to help with that effort, but at the moment I don't understand the protocol and the limited documentation I've been able to find isn't especially helpful.

I'm also willing to try reproducing this problem in a different way but I'm not sure I understand what you're asking me to do. Can I just invoke sysctl and ulimit with the parameters you've specified and try what I did before, looking for core files in the current directory, or is there more to it?

This is less important, but I'm also confused about about the theory. It appears (and this may just be my own confusion) that you're suggesting gnupg-pkcs11-scd is crashing, being restarted and then ignoring the log-file and debug directives in its configuration file. Is that right? Would it not be a simpler to conclude that gnupg is getting confused by the output of SCD LEARN and either crashing or not issuing SCD GETATTR or SCD READKEY commands?

[saper]

Please excuse my babble. Do you see any SCD READKEY in your log at all? The log looks kind of short to me, but maybe this is the problem.

[antimeme]

Do you see any SCD READKEY in your log at all?

No. I just tried again. I get thirty lines (like the ones I posted above) from the RELOADAGENT and SCD LEARN lines, but nothing gets added when I run gpg --expert --full-generate-key at all. There are still 30 lines afterward and no instance of READKEY in the file before or after. Also, I ran the ulimit and sysctl lines before hand as you suggested, but I see no core files in /tmp or the current directory. Is it possible that wasn't enough to outwit the enterprise core hiding?

Also, I can invoke READKEY using gpg-connect-agent but while that produces plausible output (see above) that also doesn't add any lines to the agent log.

[saper]

Can you stop doing the reload and learn steps?

Just try

gpg-connect-agent 'scd getinfo pid' 'getinfo pid' /bye
: > /tmp/agent.log
* make sure only one agent and one gnupkg-pkcs11-scd are running
gpg --full-generate-key --expert
(pick up 14)
gpg-connect-agent 'scd getinfo pid' 'getinfo pid' /bye

The log we have comes from a separate agent instance invoked by echo -e 'RELOADAGENT\nSCD LEARN' | gpg-agent --server gpg-connect-agent we don't need that now.

[antimeme]

Here's the output:

$ gpg-connect-agent 'scd getinfo pid' 'getinfo pid' /bye
D 956542
OK
D 956532
OK
$ : > /tmp/agent.log 
$ gpg --full-generate-key --expert
gpg (GnuPG) 2.2.20; Copyright (C) 2020 Free Software Foundation, Inc.
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.

Please select what kind of key you want:
   (1) RSA and RSA (default)
   (2) DSA and Elgamal
   (3) DSA (sign only)
   (4) RSA (sign only)
   (7) DSA (set your own capabilities)
   (8) RSA (set your own capabilities)
   (9) ECC and ECC
  (10) ECC (sign only)
  (11) ECC (set your own capabilities)
  (13) Existing key
  (14) Existing key from card
Your selection? 14
Serial number of the card: D27600012401115031319DE9939B1111
Available keys:
   (1) 9A986AA0B6CE0BAE5BE058DCEF13F742911DB593 pkcs11:model=;token=accelerator;manufacturer=nCipher%20Corp.%20Ltd;serial=A9DB-D03C-115F;id=%9a%98j%a0%b6%ce%0b%ae%5b%e0X%dc%ef%13%f7B%91%1d%b5%93 (null)
Your selection? 
gpg: signal Interrupt caught ... exiting
$ gpg-connect-agent 'scd getinfo pid' 'getinfo pid' /bye
D 956542
OK
D 956532
OK

The /tmp/agent.log file is completely empty. I also checked before the final step and it was empty then too. I also confirmed using ps that only one instance of gpg-agent and gnupg-pkcs11-scd were running. Not sure if I'm missing some configuration? Here is ~/.gnupg/gpg-agent.conf:

debug 0xffff
log-file /tmp/agent.log

scdaemon-program /usr/bin/gnupg-pkcs11-scd
pinentry-program /usr/bin/pinentry-tty

[saper]

I think I have managed to reproduce it by forcing the model value to be all zeros (empty string) in the debugger, kind of simulating your token.

2024-10-01 18:59:13 gpg-agent[90672] DBG: chan_9 <- S KEY-FRIEDNLY 63F8859168EC09711B4C16A163198FA04ECFED6F /CN=Test on loadshared accelerator
2024-10-01 18:59:13 gpg-agent[90672] DBG: chan_8 -> S KEY-FRIEDNLY 63F8859168EC09711B4C16A163198FA04ECFED6F /CN=Test on loadshared accelerator
2024-10-01 18:59:13 gpg-agent[90672] DBG: chan_9 <- S CERTINFO 101 pkcs11:model=;token=loadshared%20accelerator;manufacturer=SoftHSM%20project;serial=fe67bb79d35d2535;id=V%d4%ef%9a%5c%eav%fc%adsG%1b3I%a4W%a1%ea%ff%f0
2024-10-01 18:59:13 gpg-agent[90672] DBG: chan_8 -> S CERTINFO 101 pkcs11:model=;token=loadshared%20accelerator;manufacturer=SoftHSM%20project;serial=fe67bb79d35d2535;id=V%d4%ef%9a%5c%eav%fc%adsG%1b3I%a4W%a1%ea%ff%f0
2024-10-01 18:59:13 gpg-agent[90672] DBG: chan_9 <- S KEYPAIRINFO 63F8859168EC09711B4C16A163198FA04ECFED6F pkcs11:model=;token=loadshared%20accelerator;manufacturer=SoftHSM%20project;serial=fe67bb79d35d2535;id=V%d4%ef%9a%5c%eav%fc%adsG%1b3I%a4W%a1%ea%ff%f0
2024-10-01 18:59:13 gpg-agent[90672] DBG: chan_8 -> S KEYPAIRINFO 63F8859168EC09711B4C16A163198FA04ECFED6F pkcs11:model=;token=loadshared%20accelerator;manufacturer=SoftHSM%20project;serial=fe67bb79d35d2535;id=V%d4%ef%9a%5c%eav%fc%adsG%1b3I%a4W%a1%ea%ff%f0
2024-10-01 18:59:13 gpg-agent[90672] DBG: chan_9 <- OK
2024-10-01 18:59:13 gpg-agent[90672] DBG: chan_8 -> OK
2024-10-01 18:59:13 gpg-agent[90672] DBG: chan_8 <- SCD GETATTR $AUTHKEYID
2024-10-01 18:59:13 gpg-agent[90672] DBG: chan_9 -> GETATTR $AUTHKEYID
2024-10-01 18:59:13 gpg-agent[90672] DBG: chan_9 <- ERR 79 Invalid data <Unspecified source>
2024-10-01 18:59:13 gpg-agent[90672] DBG: chan_8 -> ERR 79 Invalid data <Unspecified source>
2024-10-01 18:59:13 gpg-agent[90672] DBG: chan_8 <- SCD GETATTR $ENCRKEYID
2024-10-01 18:59:13 gpg-agent[90672] DBG: chan_9 -> GETATTR $ENCRKEYID
2024-10-01 18:59:13 gpg-agent[90672] DBG: chan_9 <- ERR 79 Invalid data <Unspecified source>
2024-10-01 18:59:13 gpg-agent[90672] DBG: chan_8 -> ERR 79 Invalid data <Unspecified source>
2024-10-01 18:59:13 gpg-agent[90672] DBG: chan_8 <- SCD GETATTR $SIGNKEYID
2024-10-01 18:59:13 gpg-agent[90672] DBG: chan_9 -> GETATTR $SIGNKEYID
2024-10-01 18:59:13 gpg-agent[90672] DBG: chan_9 <- ERR 79 Invalid data <Unspecified source>
2024-10-01 18:59:13 gpg-agent[90672] DBG: chan_8 -> ERR 79 Invalid data <Unspecified source>
2024-10-01 18:59:13 gpg-agent[90672] DBG: chan_8 <- SCD READKEY --info -- pkcs11:model=;token=loadshared%20accelerator;manufacturer=SoftHSM%20project;serial=fe67bb79d35d2535;id=V%d4%ef%9a%5c%eav%fc%adsG%1b3I%a4W%a1%ea%ff%f0
2024-10-01 18:59:13 gpg-agent[90672] DBG: chan_9 -> READKEY --info -- pkcs11:model=;token=loadshared%20accelerator;manufacturer=SoftHSM%20project;serial=fe67bb79d35d2535;id=V%d4%ef%9a%5c%eav%fc%adsG%1b3I%a4W%a1%ea%ff%f0
2024-10-01 18:59:13 gpg-agent[90672] DBG: chan_9 <- ERR 27 Not found <Unspecified source>
2024-10-01 18:59:13 gpg-agent[90672] DBG: chan_8 -> ERR 27 Not found <Unspecified source>

Looks like the PKCS#11 generator produces empty model= but as a result the token cannot be found if we give it a pkcs11: URI.

@alonbl mentioned this problem in the review https://github.com/OpenSC/pkcs11-helper/pull/4#issuecomment-459986080

[saper]

The /tmp/agent.log file is completely empty

Something something file permissions, SELinux, whatever...? Some other writable location, maybe?

Here is my config that works on FreeBSD

scdaemon-program /usr/local/bin/gnupg-pkcs11-scd
pinentry-program /usr/local/bin/pinentry-dmenu
debug 0xffff
log-file /tmp/agent.log

[antimeme]

Does this mean the Fedora/EPEL patch can be updated to include a non-empty model value and as a consequence allow gnupg to recognize PKCS#11 key pairs? If so that would seem to mean gnupg could work with PKCS#11 with or without the patch, which seems like progress.

[antimeme]

Something something file permissions, SELinux, whatever...?

I just tried again with SELinux disabled (sudo setenforce 0) but still nothing in the log.

$ ls -l /tmp/agent.log
-rw-r--r--. 1 user user   0 Oct  1 13:17 /tmp/agent.log

[saper]

I don't know. Accepting partial URIs could mean they are not unique anymore and multiple tokens match. But I have a (software) token that generates 32 virtual PKCS#11 slots, all with the same PKCS#11 URI, so maybe nobody cares.

I hope you can get your agent.log out there and confirm what I can see.

[saper]

I just tried again with SELinux disabled (sudo setenforce 0) but still nothing in the log.

I am sorry for this. No idea. I think I've spent enough time on this, thank you!

[dwmw2]

Looks like the PKCS#11 generator produces empty model=

I think that part is valid, isn't it? If the model reported by the token really is empty, then the URI should specify a token with model=.

but as a result the token cannot be found if we give it a pkcs11: URI.

That part seems like the bug, I think? On the matching side? Specifically, if a URI specifies an empty model= then that should match the original token which reports an empty model field. It shouldn't result in the token not being found.

@alonbl mentioned this problem in the review https://github.com/OpenSC/pkcs11-helper/pull/4#issuecomment-459986080>

Hm? I see no mention of empty fields, or of the model field, there?

[saper]

Hm? I see no mention of empty fields, or of the model field, there?

"it supports only full pkcs11 url" is how I understand what is being said. I think this was a known limitation from the start, you might call it a "bug". Sorry that @antimeme apparently got hit by this.

[antimeme]

I checked and the PKCS#11 token I'm using does indeed have a model value in CK_TOKEN_INFO consisting of 16 blank spaces. So the URI is at least conceptually correct, even if it might be confusing either gnupg-pkcs11-scd or gnupg itself.

[saper]

2.5. PKCS #11 URI Matching Guidelines

o An attribute not present in the URI path component but known to a consumer matches everything. Each additional attribute present in the URI path component further restricts the selection.

o A logical extension of the above is that a URI with an empty path component matches everything. For example, if used to identify storage objects, it matches all accessible objects in all tokens provided by all relevant PKCS #11 API producers.

PKCS#11 URI are more like a query language, not unique identifiers

[dwmw2]

PKCS#11 URI are more like a query language, not unique identifiers

Right. That's fundamentally the nature of PKCS#11 itself, which is why the standardized URI description format is that way.

The issue here is because the underlying token matching code in pkcs11-helper assumed that it would be given all of model, label, manufacturerID and label to match on, as the the previous proprietary serialization format included all four.

Making it require PKCS#11 URIs with all four was a reasonable first step, in theory. Because it also created URIs with all four. So in theory it could still be used to pass serialized IDs to itself as before (and yes, those were always really search parameters not really unique identifiers). But it did so in the standard format and also accepted the standard format... as long as you specify all four fields.

So it wasn't a regression — in theory — it was still an expansion of its capabilities. There was scope for a follow-on patch to rework the token matching code once the first, simpler patches were merged. And make it support partial matches too.

I've said "in theory" a few times because in practice, we now see that it treats an empty model= exactly the same as having no model= parameter. That's the bug here; it should accept model= as meaning precisely what's in @antimeme's token — 16 blank spaces (since PKCS#11 strings are like that, not NUL-terminated).

[dwmw2]

Please could you test with this patch? I'm afraid I've only compile-tested it so far: https://github.com/OpenSC/pkcs11-helper/pull/4/commits/94b0adf4b3be6ee359c4f46ec517b81aca9d8a9a

[dwmw2]

Any word on testing?

[antimeme]

I haven't had time. I'll try to get to it next week if possible.