Bug 1543566 - ssh-pkcs11-helper fails under multiple requests
Summary: ssh-pkcs11-helper fails under multiple requests
Status: CLOSED NOTABUG
Alias: None
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: openssh
Version: 7.4
Hardware: x86_64
OS: Linux
unspecified
medium
Target Milestone: rc
: ---
Assignee: Jakub Jelen
QA Contact: BaseOS QE Security Team
URL:
Whiteboard:
Keywords:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2018-02-08 17:59 UTC by Orion Poplawski
Modified: 2018-08-13 07:56 UTC (History)
1 user (show)

(edit)
Clone Of:
(edit)
Last Closed: 2018-02-23 15:56:16 UTC


Attachments (Terms of Use)
/tmp/opensc-debug.log.gz (838.23 KB, application/x-gzip)
2018-02-22 17:00 UTC, Orion Poplawski
no flags Details

Description Orion Poplawski 2018-02-08 17:59:59 UTC
Description of problem:

I'm starting to try to use my YubiKey 4 to store a ssh-key.  I've added the key to my agent with:

ssh-add -s /usr/lib64/opensc-pkcs11.so

If I launch ansible-playbook with a moderate amount of hosts (about 40), the ssh connections will fail.  The system logs report:


Feb 08 10:36:55 barry.cora.nwra.com ssh-pkcs11-helper[18986]: error: C_Sign failed: 5
Feb 08 10:36:55 barry.cora.nwra.com ssh-agent[18954]: error: process_sign_request2: sshkey_sign: error in libcrypto
Feb 08 10:36:56 barry.cora.nwra.com ssh-pkcs11-helper[18986]: error: C_Sign failed: 32
Feb 08 10:36:56 barry.cora.nwra.com ssh-agent[18954]: error: process_sign_request2: sshkey_sign: error in libcrypto
Feb 08 10:36:59 barry.cora.nwra.com ssh-pkcs11-helper[18986]: error: C_Sign failed: 32
Feb 08 10:36:59 barry.cora.nwra.com ssh-agent[18954]: error: process_sign_request2: sshkey_sign: error in libcrypto
Feb 08 10:37:00 barry.cora.nwra.com ssh-pkcs11-helper[18986]: error: C_Sign failed: 32
Feb 08 10:37:00 barry.cora.nwra.com ssh-agent[18954]: error: process_sign_request2: sshkey_sign: error in libcrypto
Feb 08 10:37:00 barry.cora.nwra.com ssh-pkcs11-helper[18986]: error: C_Sign failed: 257
Feb 08 10:37:00 barry.cora.nwra.com ssh-agent[18954]: error: process_sign_request2: sshkey_sign: error in libcrypto
Feb 08 10:37:00 barry.cora.nwra.com ssh-pkcs11-helper[18986]: error: cannot find private key
Feb 08 10:37:00 barry.cora.nwra.com ssh-agent[18954]: error: process_sign_request2: sshkey_sign: error in libcrypto
...

Not sure if this is really an openssh issue or further down the library stack, but starting here.

Version-Release number of selected component (if applicable):
openssh-7.4p1-13.el7_4.x86_64
openssl-1.0.2k-8.el7.x86_64
opensc-0.16.0-5.20170227git777e2a3.el7.x86_64
pcsc-lite-1.8.8-6.el7.x86_64


How reproducible:
Nearly every time.

Comment 2 Orion Poplawski 2018-02-08 18:40:56 UTC
Hmm, not sure it's dependent on multiple accesses.  If I limit forks to 1 in ansible.cfg I still get failures.  This is becoming more of a show stopper.

Comment 3 Orion Poplawski 2018-02-08 19:41:30 UTC
FWIW - Errors we are seeing:

#define CKR_GENERAL_ERROR                0x00000005
#define CKR_DATA_INVALID                 0x00000020
#define CKR_USER_NOT_LOGGED_IN           0x00000101

With forks=1, I tend to see:

Feb 08 12:35:05 barry.cora.nwra.com ssh-pkcs11-helper[18986]: error: C_Sign failed: 257
Feb 08 12:35:05 barry.cora.nwra.com ssh-agent[18954]: error: process_sign_request2: sshkey_sign: error in libcrypto
Feb 08 12:35:17 barry.cora.nwra.com ssh-pkcs11-helper[18986]: error: cannot find private key
Feb 08 12:35:17 barry.cora.nwra.com ssh-agent[18954]: error: process_sign_request2: sshkey_sign: error in libcrypto
...

Comment 4 Jakub Jelen 2018-02-09 08:32:49 UTC
Can you authenticate with the card from ssh-agent with normal single ssh connection (or two one after the other?).

What private key slot are you using? The key in "Signature Key" slot in PIV applet (on Yubikey), requires special handling (pin verification before each connection) [1] and OpenSSH ssh-agent does not support that [2] at the moment.

As a workaround, you can try to configure OpenSC according to the documentation [3] with pin_cache_ignore_user_consent, which might solve your problems.

Other possibility is to load the private key in some other slot, that does not enforce this requirement.

[1] http://nvlpubs.nist.gov/nistpubs/ir/2015/NIST.IR.7863.pdf
[2] https://bugzilla.mindrot.org/show_bug.cgi?id=2638
[3] https://access.redhat.com/articles/3034441

Comment 5 Orion Poplawski 2018-02-09 17:35:41 UTC
Thanks for the quick response.  This may be running into usb issues on specific machines.  Testing it out on my laptop and so far so good.  On the laptop I get lots of these messages:

kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 4 ep 4 with no TDs queued?

but so far no ssh failures.

ssh connections can work fine, it's intermittent.

I setup the yubikey with the yubikey-piv-manager on Windows, looks like it installs the key/certificate in slot 9a - PIV Authentication, not 9c which I think would be your "Signature Key" or "Digital Signature" slot - https://developers.yubico.com/PIV/Introduction/Certificate_slots.html

Comment 6 Jakub Jelen 2018-02-10 16:56:12 UTC
There might be some concurrency issues in either ssh-agent or opensc itself, but ssh-agent is opening only single connection to the pkcs11 driver, which should serialize all the requests for signatures.

You can try to configure the OpenSC to generate a debug logs by uncommenting

  debug_file = /tmp/opensc-debug.log

in /etc/opensc-x86_64.conf

It will generate a lot of information, which might show some error. But if it is really USB related I don't think I will be able to help you.

Comment 7 Orion Poplawski 2018-02-22 17:00 UTC
Created attachment 1399488 [details]
/tmp/opensc-debug.log.gz

Here's the debug log.  There are certainly errors, starting with:

0x7f298d101740 09:49:40.107 [opensc-pkcs11] card-piv.c:533:piv_general_io: DEE r=0 apdu.resplen=0 s
w1=6a sw2=82
0x7f298d101740 09:49:40.107 [opensc-pkcs11] iso7816.c:121:iso7816_check_sw: File not found
0x7f298d101740 09:49:40.107 [opensc-pkcs11] card-piv.c:544:piv_general_io: Card returned error
0x7f298d101740 09:49:40.107 [opensc-pkcs11] card.c:445:sc_unlock: called
0x7f298d101740 09:49:40.107 [opensc-pkcs11] reader-pcsc.c:627:pcsc_unlock: called
0x7f298d101740 09:49:40.109 [opensc-pkcs11] card-piv.c:595:piv_general_io: returning with: -1201 (File not found)
0x7f298d101740 09:49:40.109 [opensc-pkcs11] card-piv.c:960:piv_get_data: returning with: -1201 (File not found)
0x7f298d101740 09:49:40.109 [opensc-pkcs11] card-piv.c:1040:piv_get_cached_data: returning with: -1201 (File not found)

.....

0x7f298d101740 09:49:40.129 [opensc-pkcs11] dir.c:163:sc_enum_apps: called
0x7f298d101740 09:49:40.129 [opensc-pkcs11] card.c:709:sc_select_file: called; type=2, path=3f002f00
0x7f298d101740 09:49:40.129 [opensc-pkcs11] card-piv.c:2481:piv_select_file: called
0x7f298d101740 09:49:40.129 [opensc-pkcs11] card-piv.c:403:piv_find_obj_by_containerid: called
0x7f298d101740 09:49:40.129 [opensc-pkcs11] card-piv.c:404:piv_find_obj_by_containerid: str=0x2F00
0x7f298d101740 09:49:40.129 [opensc-pkcs11] card-piv.c:411:piv_find_obj_by_containerid: returning with: -1 (Unknown error)
0x7f298d101740 09:49:40.129 [opensc-pkcs11] card-piv.c:2505:piv_select_file: returning with: -1201 (File not found)
0x7f298d101740 09:49:40.129 [opensc-pkcs11] card.c:731:sc_select_file: 'SELECT' error: -1201 (File not found)
0x7f298d101740 09:49:40.129 [opensc-pkcs11] dir.c:171:sc_enum_apps: Cannot select EF.DIR file: -1201 (File not found)

and so forth.

Comment 8 Orion Poplawski 2018-02-22 22:24:38 UTC
Some more info - I have two USB controllers in this box and I get the pkcs11 errors using either one.  But again, it works fine on my laptop so I really don't know what is going on.  Unfortunately I cannot try mainline or lt kernels (without a lot more pain) because I need the nvidia binary graphics driver.

Comment 9 Jakub Jelen 2018-02-23 09:58:37 UTC
In the log, I see something weird. There is too many C_OpenSession() calls, but this function should be called only once, while adding a card to the agent.

Is this log from single invocation of ssh-agent and single ssh-add and then several ssh-connections?

Don't you have PKCS11Provider options specified someplace in your ssh_config, which could interfere with the long-running session in the agent?

Comment 10 Orion Poplawski 2018-02-23 15:26:42 UTC
That was it!  Thank you!  I still had a ~/.ssh/config option from initial testing.  Removing that fixes the issue.  I'll let you decide whether to close this as an unsupported configuration or if ssh should somehow support this better.

Comment 11 Jakub Jelen 2018-02-23 15:56:16 UTC
Coincidentally I was investigating this issue in upstream OpenSSH [1]. There is no way how to fix it from OpenSSH side, but it will be fixed in next OpenSC.

Until that, it is probably misconfiguration. Closing as that.

[1] https://bugzilla.mindrot.org/show_bug.cgi?id=2635

Comment 12 William Brown 2018-08-09 22:51:21 UTC
Hi,

This still may be a bug. I can reproduce this, but in a different way. It looks like if the CCID has multiple slots, the opensc process is now only using the first slot during the pkcs11 action for ssh.

So if I have the SSH key in slot 9c, and a usercertificate in slot 9a, this fails with the libcrypto error here,

However, if I use the certificate in slot 9a, the operation succeeds.

Comment 13 Jakub Jelen 2018-08-13 07:55:00 UTC
Please, open a new bug with some more debugging information. This is probably some different issue, but from these two paragraph, it is hard to guess.

But I assume the 9c slot is Digital Signature slot, which requires non-repudiation [1]:

> The PIN must be submitted every time immediately before a sign operation, to ensure cardholder participation for every digital signature generated.

which is not supported and silently ignored for years in OpenSSH [2].

[1] https://developers.yubico.com/PIV/Introduction/Certificate_slots.html
[2] https://bugzilla.mindrot.org/show_bug.cgi?id=2638

Comment 14 Jakub Jelen 2018-08-13 07:56:20 UTC
Moreover using the Digital Signature key for authentication is wrong -- you should use any other slot, but generally Authentication slot should be fine.


Note You need to log in before you can comment on or make changes to this bug.