Bug 1460226 - gnupg stopped working for yubikey 4
gnupg stopped working for yubikey 4
Status: NEW
Product: Fedora
Classification: Fedora
Component: gnupg2 (Show other bugs)
27
Unspecified Unspecified
unspecified Severity unspecified
: ---
: ---
Assigned To: Tomas Mraz
Fedora Extras Quality Assurance
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2017-06-09 08:16 EDT by Christian Kellner
Modified: 2018-01-16 10:30 EST (History)
9 users (show)

See Also:
Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed:
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
pcscd log (361.72 KB, text/plain)
2017-06-10 07:04 EDT, Christian Kellner
no flags Details

  None (edit)
Description Christian Kellner 2017-06-09 08:16:23 EDT
My yubikey 4 has stopped working with gpg(2) [gnupg2-2.1.21-2.fc27]:

opensc-tool --reader 0 --name -v
Connecting to card in reader Yubico Yubikey 4 OTP+U2F+CCID 00 00...
Using card driver PIV-II  for multiple cards.
Card name: PIV-II card

--- 8< ---

gpg2 --card-edit

gpg: selecting openpgp failed: No such device
gpg: OpenPGP card not available: No such device

--- >8 ---

gpg --card-edit

gpg: detected reader `Yubico Yubikey 4 OTP+U2F+CCID 00 00'
gpg: pcsc_connect failed: sharing violation (0x8010000b)
gpg: apdu_send_simple(0) failed: locking failed
Please insert the card and hit return or enter 'c' to cancel:

--- 8< ---

pcsc_scan
PC/SC device scanner
V 1.4.25 (c) 2001-2011, Ludovic Rousseau <ludovic.rousseau@free.fr>
Compiled with PC/SC lite version: 1.8.20
Using reader plug'n play mechanism
Scanning present readers...
0: Yubico Yubikey 4 OTP+U2F+CCID 00 00

Fri Jun  9 13:26:45 2017
Reader 0: Yubico Yubikey 4 OTP+U2F+CCID 00 00
  Card state: Card inserted, Shared Mode, 
  ATR: 3B F8 13 00 00 81 31 FE 15 59 75 62 69 6B 65 79 34 D4

ATR: 3B F8 13 00 00 81 31 FE 15 59 75 62 69 6B 65 79 34 D4
+ TS = 3B --> Direct Convention
+ T0 = F8, Y(1): 1111, K: 8 (historical bytes)
  TA(1) = 13 --> Fi=372, Di=4, 93 cycles/ETU
    43010 bits/s at 4 MHz, fMax for Fi = 5 MHz => 53763 bits/s
  TB(1) = 00 --> VPP is not electrically connected
  TC(1) = 00 --> Extra guard time: 0
  TD(1) = 81 --> Y(i+1) = 1000, Protocol T = 1 
-----
  TD(2) = 31 --> Y(i+1) = 0011, Protocol T = 1 
-----
  TA(3) = FE --> IFSC: 254
  TB(3) = 15 --> Block Waiting Integer: 1 - Character Waiting Integer: 5
+ Historical bytes: 59 75 62 69 6B 65 79 34
  Category indicator byte: 59 (proprietary format)
+ TCK = D4 (correct checksum)

Possibly identified card (using /usr/share/pcsc/smartcard_list.txt):
3B F8 13 00 00 81 31 FE 15 59 75 62 69 6B 65 79 34 D4
	Yubico Yubikey 4 OTP+CCID

--- >8 ---

cat .gnupg/reader_0.status
NOCARD

--- 8< ---

 cat scdaemon.log 
2017-06-09 14:03:20 scdaemon[31471] listening on socket '/run/user/1000/gnupg/S.scdaemon'
2017-06-09 14:03:20 scdaemon[31471] handler for fd -1 started
2017-06-09 14:03:20 scdaemon[31471] DBG: chan_5 -> OK GNU Privacy Guard's Smartcard server ready
2017-06-09 14:03:40 scdaemon[31856] listening on socket '/run/user/1000/gnupg/S.scdaemon'
2017-06-09 14:03:40 scdaemon[31856] handler for fd -1 started
2017-06-09 14:03:40 scdaemon[31856] DBG: chan_5 -> OK GNU Privacy Guard's Smartcard server ready
2017-06-09 14:03:40 scdaemon[31856] DBG: chan_5 <- GETINFO socket_name
2017-06-09 14:03:40 scdaemon[31856] DBG: chan_5 -> D /run/user/1000/gnupg/S.scdaemon
2017-06-09 14:03:40 scdaemon[31856] DBG: chan_5 -> OK
2017-06-09 14:03:40 scdaemon[31856] DBG: chan_5 <- OPTION event-signal=12
2017-06-09 14:03:40 scdaemon[31856] DBG: chan_5 -> OK
2017-06-09 14:03:40 scdaemon[31856] DBG: chan_5 <- GETINFO version
2017-06-09 14:03:40 scdaemon[31856] DBG: chan_5 -> D 2.1.21
2017-06-09 14:03:40 scdaemon[31856] DBG: chan_5 -> OK
2017-06-09 14:03:40 scdaemon[31856] DBG: chan_5 <- SERIALNO openpgp
2017-06-09 14:03:40 scdaemon[31856] DBG: apdu_open_reader: BAI=10e02
2017-06-09 14:03:40 scdaemon[31856] DBG: apdu_open_reader: new device=10e02
2017-06-09 14:03:40 scdaemon[31856] ccid open error: skip
2017-06-09 14:03:40 scdaemon[31856] DBG: enter: apdu_open_reader: portstr=(null)
2017-06-09 14:03:40 scdaemon[31856] detected reader 'Yubico Yubikey 4 OTP+U2F+CCID 00 00'
2017-06-09 14:03:40 scdaemon[31856] detected reader ''
2017-06-09 14:03:40 scdaemon[31856] reader slot 0: not connected
2017-06-09 14:03:40 scdaemon[31856] DBG: leave: apdu_open_reader => slot=0 [pc/sc]
2017-06-09 14:03:40 scdaemon[31856] DBG: enter: apdu_connect: slot=0
2017-06-09 14:03:40 scdaemon[31856] pcsc_connect failed: sharing violation (0x8010000b)
2017-06-09 14:03:40 scdaemon[31856] reader slot 0: not connected
2017-06-09 14:03:40 scdaemon[31856] DBG: leave: apdu_connect => sw=0x10006
2017-06-09 14:03:40 scdaemon[31856] DBG: enter: apdu_close_reader: slot=0
2017-06-09 14:03:40 scdaemon[31856] DBG: enter: apdu_disconnect: slot=0
2017-06-09 14:03:40 scdaemon[31856] DBG: leave: apdu_disconnect => sw=0x0
2017-06-09 14:03:40 scdaemon[31856] DBG: leave: apdu_close_reader => 0x0 (close_reader)
2017-06-09 14:03:40 scdaemon[31856] DBG: chan_5 -> ERR 100696144 No such device <SCD>
2017-06-09 14:03:40 scdaemon[31856] DBG: chan_5 <- RESTART
2017-06-09 14:03:40 scdaemon[31856] DBG: chan_5 -> OK

--- >8 ---

I dug around and found a outdated upstream bug (https://dev.gnupg.org/T2933) that looks very similar, but the fix should already be in (the fix was released in 2.1.19 and also the "disable-ccid" option didn't seem to do anything.
BUT, stopping the pcscd daemon/socket made the yubikey work again.


Here is the log from the successful attempt: 
--- 8< ---
017-06-09 14:06:24 scdaemon[480] listening on socket '/run/user/1000/gnupg/S.scdaemon'
2017-06-09 14:06:24 scdaemon[480] handler for fd -1 started
2017-06-09 14:06:24 scdaemon[480] DBG: chan_5 -> OK GNU Privacy Guard's Smartcard server ready
2017-06-09 14:06:49 scdaemon[31856] DBG: chan_5 <- GETINFO version
2017-06-09 14:06:49 scdaemon[31856] DBG: chan_5 -> D 2.1.21
2017-06-09 14:06:49 scdaemon[31856] DBG: chan_5 -> OK
2017-06-09 14:06:49 scdaemon[31856] DBG: chan_5 <- SERIALNO openpgp
2017-06-09 14:06:49 scdaemon[31856] DBG: apdu_open_reader: BAI=11102
2017-06-09 14:06:49 scdaemon[31856] DBG: apdu_open_reader: new device=11102
2017-06-09 14:06:49 scdaemon[31856] reader slot 0: using ccid driver
2017-06-09 14:06:49 scdaemon[31856] slot 0: ATR=3B F8 13 00 00 81 31 FE 15 59 75 62 69 6B 65 79 34 D4
2017-06-09 14:06:49 scdaemon[31856] DBG: enter: apdu_connect: slot=0
2017-06-09 14:06:49 scdaemon[31856] DBG: leave: apdu_connect => sw=0x0
2017-06-09 14:06:49 scdaemon[31856] DBG: send apdu: c=00 i=A4 p1=00 p2=0C lc=2 le=-1 em=0
2017-06-09 14:06:49 scdaemon[31856] DBG:  raw apdu: 00 A4 00 0C 02 3F 00
2017-06-09 14:06:49 scdaemon[31856] DBG:  response: sw=6D00  datalen=0
2017-06-09 14:06:49 scdaemon[31856] DBG: send apdu: c=00 i=A4 p1=04 p2=00 lc=6 le=-1 em=0
2017-06-09 14:06:49 scdaemon[31856] DBG:  raw apdu: 00 A4 04 00 06 D2 76 00 01 24 01
2017-06-09 14:06:49 scdaemon[31856] DBG:  response: sw=9000  datalen=0
2017-06-09 14:06:49 scdaemon[31856] DBG:     dump:  
2017-06-09 14:06:49 scdaemon[31856] DBG: send apdu: c=00 i=CA p1=00 p2=4F lc=-1 le=256 em=0
2017-06-09 14:06:49 scdaemon[31856] DBG:  raw apdu: 00 CA 00 4F 00
2017-06-09 14:06:49 scdaemon[31856] DBG:  response: sw=9000  datalen=16
2017-06-09 14:06:49 scdaemon[31856] DBG:       dump:  D2 76 00 01 24 01 02 01 00 06 04 15 65 74 00 00
2017-06-09 14:06:49 scdaemon[31856] AID: D2 76 00 01 24 01 02 01 00 06 04 15 65 74 00 00
2017-06-09 14:06:49 scdaemon[31856] DBG: send apdu: c=00 i=CA p1=5F p2=52 lc=-1 le=256 em=0
2017-06-09 14:06:49 scdaemon[31856] DBG:  raw apdu: 00 CA 5F 52 00
2017-06-09 14:06:49 scdaemon[31856] DBG:  response: sw=9000  datalen=8
2017-06-09 14:06:49 scdaemon[31856] DBG:       dump:  00 73 00 00 80 05 90 00
2017-06-09 14:06:49 scdaemon[31856] Historical Bytes: 00 73 00 00 80 05 90 00
2017-06-09 14:06:49 scdaemon[31856] DBG: send apdu: c=00 i=CA p1=00 p2=C4 lc=-1 le=256 em=0
2017-06-09 14:06:49 scdaemon[31856] DBG:  raw apdu: 00 CA 00 C4 00
2017-06-09 14:06:49 scdaemon[31856] DBG:  response: sw=9000  datalen=7
2017-06-09 14:06:49 scdaemon[31856] DBG:       dump:  00 7F 7F 7F 03 03 03
2017-06-09 14:06:49 scdaemon[31856] DBG: send apdu: c=00 i=CA p1=00 p2=6E lc=-1 le=256 em=0
2017-06-09 14:06:49 scdaemon[31856] DBG:  raw apdu: 00 CA 00 6E 00
2017-06-09 14:06:49 scdaemon[31856] DBG:  response: sw=9000  datalen=224
2017-06-09 14:06:49 scdaemon[31856] DBG:       dump:  6E 81 DD 4F 10 D2 76 00 01 24 01 02 01 00 06 04 15 65 74 00 00 5F 52 08 00 73 00 00 80 05 90 00 7F 74 03 81 01 20 73 81 B7 C0 0A 3C 00 00 00 04 C0 00 FF 00 FF C1 06 01 08 00 00 11 00 C2 06 01 08 00 00 11 00 C3 06 01 08 00 00 11 00 C4 07 00 7F 7F 7F 03 03 03 C5 3C 5F 2D 15 15 07 0B 19 AD F4 A6 4E C6 8C 16 79 12 4D EC 77 C7 31 BB 67 29 61 0C 30 03 89 AE 6D 55 4A B6 A2 BA AE F4 4C A5 41 22 63 A1 D5 F3 98 30 F6 7D D6 77 14 3D F9 8D 05 3B EC 11 C6 3C 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 CD 0C 56 F1 B4 E5 56 F1 B5 24 56 F1 B4 8D
2017-06-09 14:06:49 scdaemon[31856] DBG: send apdu: c=00 i=CA p1=7F p2=74 lc=-1 le=256 em=0
2017-06-09 14:06:49 scdaemon[31856] DBG:  raw apdu: 00 CA 7F 74 00
2017-06-09 14:06:49 scdaemon[31856] DBG:  response: sw=9000  datalen=3
2017-06-09 14:06:49 scdaemon[31856] DBG:       dump:  81 01 20
2017-06-09 14:06:49 scdaemon[31856] DBG: send apdu: c=00 i=CA p1=00 p2=5E lc=-1 le=256 em=0
2017-06-09 14:06:49 scdaemon[31856] DBG:  raw apdu: 00 CA 00 5E 00
2017-06-09 14:06:49 scdaemon[31856] DBG:  response: sw=9000  datalen=5
2017-06-09 14:06:49 scdaemon[31856] DBG:       dump:  67 69 63 6D 6F
2017-06-09 14:06:49 scdaemon[31856] Version-2 ......: yes
2017-06-09 14:06:49 scdaemon[31856] Get-Challenge ..: no
2017-06-09 14:06:49 scdaemon[31856] Key-Import .....: yes
2017-06-09 14:06:49 scdaemon[31856] Change-Force-PW1: yes
2017-06-09 14:06:49 scdaemon[31856] Private-DOs ....: yes
2017-06-09 14:06:49 scdaemon[31856] Algo-Attr-Change: yes
2017-06-09 14:06:49 scdaemon[31856] SM-Support .....: no
2017-06-09 14:06:49 scdaemon[31856] Max-Cert3-Len ..: 1216
2017-06-09 14:06:49 scdaemon[31856] Cmd-Chaining ...: yes
2017-06-09 14:06:49 scdaemon[31856] Ext-Lc-Le ......: no
2017-06-09 14:06:49 scdaemon[31856] Status Indicator: 05
2017-06-09 14:06:49 scdaemon[31856] Symmetric crypto: no
2017-06-09 14:06:49 scdaemon[31856] Button..........: yes
2017-06-09 14:06:49 scdaemon[31856] GnuPG-No-Sync ..: no
2017-06-09 14:06:49 scdaemon[31856] GnuPG-Def-PW2 ..: no

--- >8 ---

pcscd and scdaemon don't get along together (a race maybe)? 
For now I have just removed the pcsc-lite package and the yubikey works fine, but that is obviously not an actual solution.
Comment 1 Nikos Mavrogiannopoulos 2017-06-10 05:42:48 EDT
Shouldn't that be reported against gnupg?
Comment 2 Christian Kellner 2017-06-10 06:49:42 EDT
(In reply to Nikos Mavrogiannopoulos from comment #1)
> Shouldn't that be reported against gnupg?
I wasn't totally sure either, I guess it is hard to say who actually is the culprit without having found the root cause.

If pcsc-lite is installed, using it seems to to not work:
 - gpg fails with: "pcsc_connect failed: sharing violation (0x8010000b)"
 - gpg2 is using scdaemon, which first tries the ccid backend itself,
   and when that fails, also tires to use pcscd, which in turn also fails with
   the same error: "pcsc_connect failed: sharing violation (0x8010000b)"
   Relevant log:
   --- 8< ---
2017-06-09 14:03:40 scdaemon[31856] ccid open error: skip
2017-06-09 14:03:40 scdaemon[31856] DBG: enter: apdu_open_reader: portstr=(null)
2017-06-09 14:03:40 scdaemon[31856] detected reader 'Yubico Yubikey 4 OTP+U2F+CCID 00 00'
2017-06-09 14:03:40 scdaemon[31856] detected reader ''
2017-06-09 14:03:40 scdaemon[31856] reader slot 0: not connected
2017-06-09 14:03:40 scdaemon[31856] DBG: leave: apdu_open_reader => slot=0 [pc/sc]
2017-06-09 14:03:40 scdaemon[31856] DBG: enter: apdu_connect: slot=0
2017-06-09 14:03:40 scdaemon[31856] pcsc_connect failed: sharing violation (0x8010000b)
  --- >8 ---
The error code description, btw, is "The smart card cannot be accessed because of other connections outstanding."
Uninstalling pcsc makes at least gpg2 work (gpg of course, relying on pcsc doesn't work anymore).
So pcsc was my sophisticated guess. What I meant with the "race" was a total shot in the dark: maybe pcscd tries to access the yubikey at the same time as scdaemon tries to use the ccid backend and then they both fail. Although on a second though that might be non-sense because then at least one should win, I guess.

I guess I should get a debug log output from pcscd. I will try to get that later today.
Comment 3 Christian Kellner 2017-06-10 07:04 EDT
Created attachment 1286657 [details]
pcscd log

log obtained via:

sudo LIBCCID_ifdLogLevel=0x000F pcscd --foreground --debug --apdu --color | tee log.txt

from a quick look it seems that there is already a client connected, which would explain the sharing violations. Maybe (another shot in the dark) gsd-smartcard?
Comment 4 Nikos Mavrogiannopoulos 2017-06-12 03:13:01 EDT
Well pcsc-daemon is the system daemon for smart cards. If gnupg doesn't work with it, it is a problem of gnupg. I do not believe there is more we can do on that.
Comment 5 Tomas Mraz 2017-06-12 08:59:46 EDT
Christian, I'd suggest reporting the issue upstream as I do not have the Yubikey 4.
Comment 6 Taras 2017-07-14 10:41:57 EDT
The same problem on the latest Fedora 26.
Comment 7 Tomas Mraz 2017-07-17 04:06:21 EDT
Can you please report the problem upstream to https://dev.gnupg.org/ ?
Comment 8 Jan Kurik 2017-08-15 03:28:20 EDT
This bug appears to have been reported against 'rawhide' during the Fedora 27 development cycle.
Changing version to '27'.
Comment 9 Jakub Jelen 2017-11-22 11:17:39 EST
FYI this is the same issue as currently discussed in OpenSC upstream and the same as I am hitting just now:

https://github.com/OpenSC/OpenSC/issues/953#issuecomment-345551430

The gpg2 wants exclusive access, but something is accessing the yk before you do (either automatically or I do manually).

From what I see, the easiest would be for gpg not to require exclusive access, but it is probably something that is not acceptable for gpg developers.
Comment 10 Jakub Jelen 2018-01-16 09:04:05 EST
We should be able to address this issue by using different scdaemon (gnupg-pkcs11-scd), which does not require exclusive locking and uses standard PKCS#11 driver, such as OpenSC:

https://bodhi.fedoraproject.org/updates/FEDORA-2018-bfc98963aa

But
 * currently released OpenSC does not work with this version of OpenPGP applet in current Yubikey (upstream PR [1]),
 * there is no way to work with both PIV and OpenPGP applets at the same time from the same PKCS#11 module without configuration change (ongoing work in upstream [2])
 * the configuration of gnupg-pkcs11-scd itself is not exactly trivial.

[1] https://github.com/OpenSC/OpenSC/pull/1232
[2] https://github.com/OpenSC/OpenSC/issues/962
Comment 11 Nikos Mavrogiannopoulos 2018-01-16 10:30:11 EST
Furthermore gnupg-pkcs11-scd config does not support PKCS#11 URIs.

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