Package: scdaemon Version: 2.1.18-3 Severity: grave In Bug#854005, I have described a distinct issue I have experience with my Yubikey since the upgrade of the GnuPG suite from 2.1.17 to 2.1.18, and in the case of pcscd, from 1.8.19-1 to 1.8.20-1.
I am not sure what exactly is going on here. What I know is that I was able to configure my Yubikey to work in Jessie with GnuPG using a procedure I have documented here: https://anarc.at/blog/2015-12-14-yubikey-howto/ After installing a new workstation with Debian stretch, things were still working until the 2.1.18 release. The symptom is this: [996]anarcat@curie:~$ LANG=C gpg --card-status gpg: selecting openpgp failed: No such device gpg: OpenPGP card not available: No such device At first, adding "disable-ccid" to scdaemon.conf fixes the issue. But after a while, the behavior returns. I have noticed that pcscd is gone when that happens. After advice received in 854005, I have tried to uninstall pcscd to try and let scdaemon handle the device. This also fails. Here's a trace of me purging pcscd, restarting gpg-agent and trying to connect to the card. [1001]anarcat@curie:~$ sudo apt purge pcscd Lecture des listes de paquets... Fait Construction de l'arbre des dépendances Lecture des informations d'état... Fait Le paquet suivant a été installé automatiquement et n'est plus nécessaire : libccid Veuillez utiliser « sudo apt autoremove » pour le supprimer. Les paquets suivants seront ENLEVÉS : pcscd* 0 mis à jour, 0 nouvellement installés, 1 à enlever et 23 non mis à jour. Après cette opération, 205 ko d'espace disque seront libérés. Souhaitez-vous continuer ? [O/n] (Lecture de la base de données... 291154 fichiers et répertoires déjà installés.) Suppression de pcscd (1.8.20-1) ... Warning: Stopping pcscd.service, but it can still be activated by: pcscd.socket Traitement des actions différées (« triggers ») pour man-db (2.7.6.1-2) ... (Lecture de la base de données... 291142 fichiers et répertoires déjà installés.) Purge des fichiers de configuration de pcscd (1.8.20-1) ... Traitement des actions différées (« triggers ») pour systemd (232-15) ... [master ab8bc2d] committing changes in /etc after apt run Author: Antoine Beaupré <anar...@debian.org> 10 files changed, 155 deletions(-) delete mode 100755 init.d/pcscd delete mode 120000 rc0.d/K01pcscd delete mode 120000 rc1.d/K01pcscd delete mode 120000 rc2.d/S01pcscd delete mode 120000 rc3.d/S01pcscd delete mode 120000 rc4.d/S01pcscd delete mode 120000 rc5.d/S01pcscd delete mode 120000 rc6.d/K01pcscd delete mode 120000 systemd/system/sockets.target.wants/pcscd.socket [1002]anarcat@curie:~$ systemctl --user stop gpg-agent Warning: Stopping gpg-agent.service, but it can still be activated by: gpg-agent.socket gpg-agent-ssh.socket gpg-agent-extra.socket gpg-agent-browser.socket [1003]anarcat@curie:~$ ps axf | grep gpg 27310 pts/4 S+ 0:00 \_ grep gpg [1004]anarcat@curie:~$ LANG=C gpg --card-status gpg: selecting openpgp failed: No such device gpg: OpenPGP card not available: No such device Here's the output proving gpg is stopped: fév 08 12:22:09 curie systemd[1199]: Stopping GnuPG cryptographic agent and passphrase cache... fév 08 12:22:09 curie systemd[1199]: Stopped GnuPG cryptographic agent and passphrase cache. fév 08 12:22:09 curie gpg-agent[21736]: scdaemon[21738] SIGTERM received - shutting down ... fév 08 12:22:09 curie gpg-agent[21736]: SIGTERM received - shutting down ... fév 08 12:22:09 curie gpg-agent[21736]: gpg-agent (GnuPG) 2.1.18scdaemon[21738] scdaemon (GnuPG) 2.1.18 stopped fév 08 12:22:09 curie gpg-agent[21736]: stopped Here's the error when i try to access the card then: fév 08 12:24:20 curie systemd[1199]: Started GnuPG cryptographic agent and passphrase cache. fév 08 12:24:20 curie gpg-agent[27960]: gpg-agent (GnuPG) 2.1.18 starting in supervised mode. fév 08 12:24:20 curie gpg-agent[27960]: using fd 3 for std socket (/run/user/1000/gnupg/S.gpg-agent) fév 08 12:24:20 curie gpg-agent[27960]: using fd 4 for ssh socket (/run/user/1000/gnupg/S.gpg-agent.ssh) fév 08 12:24:20 curie gpg-agent[27960]: using fd 5 for extra socket (/run/user/1000/gnupg/S.gpg-agent.extra) fév 08 12:24:20 curie gpg-agent[27960]: using fd 6 for browser socket (/run/user/1000/gnupg/S.gpg-agent.browser) fév 08 12:24:20 curie gpg-agent[27960]: listening on: std=3 extra=5 browser=6 ssh=4 fév 08 12:24:20 curie gpg-agent[27960]: scdaemon[27962] ccid open error: skip the scdaemon debug logs show this: 2017-02-08 12:24:58 scdaemon[27971] listening on socket '/run/user/1000/gnupg/S.scdaemon' 2017-02-08 12:24:58 scdaemon[27971] handler for fd -1 started 2017-02-08 12:24:58 scdaemon[27971] DBG: chan_5 -> OK GNU Privacy Guard's Smartcard server ready 2017-02-08 12:24:58 scdaemon[27971] DBG: chan_5 <- GETINFO socket_name 2017-02-08 12:24:58 scdaemon[27971] DBG: chan_5 -> D /run/user/1000/gnupg/S.scdaemon 2017-02-08 12:24:58 scdaemon[27971] DBG: chan_5 -> OK 2017-02-08 12:24:58 scdaemon[27971] DBG: chan_5 <- OPTION event-signal=12 2017-02-08 12:24:58 scdaemon[27971] DBG: chan_5 -> OK 2017-02-08 12:24:58 scdaemon[27971] DBG: chan_5 <- GETINFO version 2017-02-08 12:24:58 scdaemon[27971] DBG: chan_5 -> D 2.1.18 2017-02-08 12:24:58 scdaemon[27971] DBG: chan_5 -> OK 2017-02-08 12:24:58 scdaemon[27971] DBG: chan_5 <- SERIALNO openpgp 2017-02-08 12:24:58 scdaemon[27971] DBG: apdu_open_reader: BAI=11201 2017-02-08 12:24:58 scdaemon[27971] DBG: apdu_open_reader: new device=11201 2017-02-08 12:24:58 scdaemon[27971] ccid open error: skip 2017-02-08 12:24:58 scdaemon[27971] DBG: chan_5 -> ERR 100696144 Aucun périphérique de ce type <SCD> 2017-02-08 12:24:58 scdaemon[27971] DBG: chan_5 <- RESTART 2017-02-08 12:24:58 scdaemon[27971] DBG: chan_5 -> OK Those were enabled with: printf 'debug-all\nlog-file /run/user/%d/scdaemon.log\n' "$(id -u)" >> ~/.gnupg/scdaemon.conf If I reinstall pcscd and disable-ccid in scdaemon.conf, things work again, for a while, until pcscd crashes again. Here's a working run output: [1017]anarcat@curie:~$ LANG=C gpg --card-status Reader ...........: Yubico Yubikey NEO OTP CCID 00 00 Application ID ...: XXXXXXXXXXXXXXXXXXXXXxx Version ..........: 2.0 Manufacturer .....: Yubico Serial number ....: XXXXXXXXX Name of cardholder: [not set] Language prefs ...: [not set] Sex ..............: unspecified URL of public key : [not set] Login data .......: [not set] Signature PIN ....: forced Key attributes ...: rsa2048 rsa2048 rsa2048 Max. PIN lengths .: 127 127 127 PIN retry counter : 3 3 3 Signature counter : 0 Signature key ....: [none] Encryption key....: [none] Authentication key: XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX created ....: 2012-07-20 00:17:35 General key info..: sub rsa2048/[...] and here's what i get in syslog: fév 08 12:27:06 curie systemd[1199]: Started GnuPG cryptographic agent and passphrase cache. fév 08 12:27:06 curie gpg-agent[28488]: gpg-agent (GnuPG) 2.1.18 starting in supervised mode. fév 08 12:27:06 curie gpg-agent[28488]: using fd 3 for std socket (/run/user/1000/gnupg/S.gpg-agent) fév 08 12:27:06 curie gpg-agent[28488]: using fd 4 for ssh socket (/run/user/1000/gnupg/S.gpg-agent.ssh) fév 08 12:27:06 curie gpg-agent[28488]: using fd 5 for extra socket (/run/user/1000/gnupg/S.gpg-agent.extra) fév 08 12:27:06 curie gpg-agent[28488]: using fd 6 for browser socket (/run/user/1000/gnupg/S.gpg-agent.browser) fév 08 12:27:06 curie gpg-agent[28488]: listening on: std=3 extra=5 browser=6 ssh=4 fév 08 12:27:06 curie gpg-agent[28488]: scdaemon[28490] enabled debug flags: mpi crypto memory cache memstat hashing ipc cardio reader fév 08 12:27:06 curie kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 21 ep 4 with no TDs queued? fév 08 12:27:06 curie kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 21 ep 4 with no TDs queued? fév 08 12:27:06 curie kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 21 ep 4 with no TDs queued? fév 08 12:27:06 curie kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 21 ep 4 with no TDs queued? fév 08 12:27:06 curie kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 21 ep 4 with no TDs queued? fév 08 12:27:06 curie kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 21 ep 4 with no TDs queued? fév 08 12:27:06 curie kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 21 ep 4 with no TDs queued? fév 08 12:27:06 curie kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 21 ep 4 with no TDs queued? fév 08 12:27:06 curie kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 21 ep 4 with no TDs queued? fév 08 12:27:06 curie kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 21 ep 4 with no TDs queued? fév 08 12:27:06 curie kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 21 ep 4 with no TDs queued? fév 08 12:27:06 curie pcscd[28182]: 25900973 winscard.c:283:SCardConnect() Error Reader Exclusive fév 08 12:27:06 curie kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 21 ep 4 with no TDs queued? fév 08 12:27:06 curie kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 21 ep 4 with no TDs queued? fév 08 12:27:06 curie kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 21 ep 4 with no TDs queued? fév 08 12:27:06 curie kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 21 ep 4 with no TDs queued? fév 08 12:27:06 curie kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 21 ep 4 with no TDs queued? fév 08 12:27:06 curie kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 21 ep 4 with no TDs queued? fév 08 12:27:06 curie kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 21 ep 4 with no TDs queued? fév 08 12:27:06 curie kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 21 ep 4 with no TDs queued? fév 08 12:27:06 curie kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 21 ep 4 with no TDs queued? fév 08 12:27:06 curie gpg-agent[28488]: card has S/N: XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX I haven't figured out what happens when pcscd crashes - i couldn't find anything in the syslog or anywhere. I get this error from scdaemon: fév 06 19:45:29 curie gpg-agent[1643]: scdaemon[1645] pcsc_establish_context failed: no service (0x8010001d) ... which is the same error as when pcscd is uninstalled - ie. it's not running. the reason why reinstalling pcscd fixes the issue for me is probably that it resets the systemd configuration for the daemon and reinstalling restarts it properly. now it is running - but who knows for how long? ● pcscd.service - PC/SC Smart Card Daemon Loaded: loaded (/lib/systemd/system/pcscd.service; indirect; vendor preset: enabled) Active: active (running) since Wed 2017-02-08 10:12:36 EST; 4min 1s ago Main PID: 14439 (pcscd) CGroup: /system.slice/pcscd.service └─14439 /usr/sbin/pcscd --foreground --auto-exit It seems that I need to do this reset thing every morning now, so I guess it's crashing at least every 24 hours. i have tried unplugging and replugging the yubikey, it doesn't trigger the problem. i have tried to figure out what may have happened by looking at the journald logs, but i can't figure it out. it doesn't clearly mention a crash. notice, in the log below, that i reinstalled the package at around Feb 08 10:12:36, which is when things went back to normal. yet before that, it's unclear what problem there was. you can certainly see a few instances where systemd started pcscd without it being stopped first... so there's definitely something going on there. anything i can do to improve debugging here? note that I don't *need* pcscd at all. i don't actually know what it is or what it's for. just want this yubikey to work reliably. :) [1021]anarcat@curie:~$ sudo LANG=C journalctl -u pcscd.service| cat -- Logs begin at Sat 2017-02-04 11:17:15 EST, end at Wed 2017-02-08 12:32:43 EST. -- Feb 04 12:33:58 curie systemd[1]: Started PC/SC Smart Card Daemon. Feb 04 12:33:58 curie pcscd[8947]: 00000000 ifdhandler.c:151:CreateChannelByNameOrChannel() failed Feb 04 12:33:58 curie pcscd[8947]: 00000012 readerfactory.c:1110:RFInitializeReader() Open Port 0x200000 Failed (usb:1050/0111:libudev:0:/dev/bus/usb/001/007) Feb 04 12:33:58 curie pcscd[8947]: 00000002 readerfactory.c:375:RFAddReader() Yubico Yubikey NEO OTP+CCID init failed. Feb 04 12:33:58 curie pcscd[8947]: 00341712 winscard.c:283:SCardConnect() Error Reader Exclusive Feb 04 12:44:42 curie pcscd[8947]: 99999999 winscard.c:283:SCardConnect() Error Reader Exclusive Feb 04 12:44:45 curie pcscd[8947]: 03512295 winscard.c:283:SCardConnect() Error Reader Exclusive Feb 04 13:26:51 curie pcscd[8947]: 99999999 ccid_usb.c:797:WriteUSB() write failed (1/7): -4 LIBUSB_ERROR_NO_DEVICE Feb 04 17:28:58 curie systemd[1]: Started PC/SC Smart Card Daemon. Feb 04 17:29:16 curie pcscd[31517]: 00000000 ifdhandler.c:151:CreateChannelByNameOrChannel() failed Feb 04 17:29:16 curie pcscd[31517]: 00000014 readerfactory.c:1110:RFInitializeReader() Open Port 0x200000 Failed (usb:1050/0111:libudev:0:/dev/bus/usb/001/008) Feb 04 17:29:16 curie pcscd[31517]: 00000003 readerfactory.c:375:RFAddReader() Yubico Yubikey NEO OTP+CCID init failed. Feb 04 17:53:08 curie systemd[1]: Started PC/SC Smart Card Daemon. Feb 04 17:53:08 curie pcscd[1915]: 00000000 ifdhandler.c:151:CreateChannelByNameOrChannel() failed Feb 04 17:53:08 curie pcscd[1915]: 00000018 readerfactory.c:1110:RFInitializeReader() Open Port 0x200000 Failed (usb:1050/0111:libudev:0:/dev/bus/usb/001/008) Feb 04 17:53:08 curie pcscd[1915]: 00000002 readerfactory.c:375:RFAddReader() Yubico Yubikey NEO OTP+CCID init failed. Feb 04 17:53:09 curie pcscd[1915]: 00860385 winscard.c:283:SCardConnect() Error Reader Exclusive Feb 04 18:10:35 curie pcscd[1915]: 99999999 winscard.c:283:SCardConnect() Error Reader Exclusive Feb 04 18:27:49 curie pcscd[1915]: 99999999 ccid_usb.c:1337:InterruptStop() libusb_cancel_transfer failed: -4 Feb 04 18:27:49 curie pcscd[1915]: 00400400 ccid_usb.c:797:WriteUSB() write failed (1/8): -4 LIBUSB_ERROR_NO_DEVICE Feb 06 10:55:09 curie systemd[1]: Started PC/SC Smart Card Daemon. Feb 06 10:55:09 curie pcscd[20263]: 00000000 utils.c:82:GetDaemonPid() Can't open /var/run/pcscd/pcscd.pid: No such file or directory Feb 06 10:55:09 curie pcscd[20263]: 00007301 ifdhandler.c:151:CreateChannelByNameOrChannel() failed Feb 06 10:55:09 curie pcscd[20263]: 00000009 readerfactory.c:1110:RFInitializeReader() Open Port 0x200000 Failed (usb:1050/0111:libudev:0:/dev/bus/usb/001/010) Feb 06 10:55:09 curie pcscd[20263]: 00000003 readerfactory.c:375:RFAddReader() Yubico Yubikey NEO OTP+CCID init failed. Feb 06 11:07:17 curie pcscd[20263]: 99999999 winscard.c:283:SCardConnect() Error Reader Exclusive Feb 06 12:13:37 curie pcscd[20263]: 99999999 winscard.c:283:SCardConnect() Error Reader Exclusive Feb 06 12:13:52 curie pcscd[20263]: 15281542 winscard.c:283:SCardConnect() Error Reader Exclusive Feb 06 18:27:32 curie pcscd[20263]: 99999999 ccid_usb.c:797:WriteUSB() write failed (1/10): -4 LIBUSB_ERROR_NO_DEVICE Feb 06 19:48:27 curie systemd[1]: Started PC/SC Smart Card Daemon. Feb 06 19:48:27 curie pcscd[3100]: 00000000 ifdhandler.c:151:CreateChannelByNameOrChannel() failed Feb 06 19:48:27 curie pcscd[3100]: 00000014 readerfactory.c:1110:RFInitializeReader() Open Port 0x200000 Failed (usb:1050/0111:libudev:0:/dev/bus/usb/001/013) Feb 06 19:48:27 curie pcscd[3100]: 00000003 readerfactory.c:375:RFAddReader() Yubico Yubikey NEO OTP+CCID init failed. Feb 06 19:48:49 curie pcscd[3100]: 22045135 winscard.c:283:SCardConnect() Error Reader Exclusive Feb 06 19:49:15 curie pcscd[3100]: 26297901 winscard.c:283:SCardConnect() Error Reader Exclusive Feb 06 19:49:56 curie pcscd[3100]: 41260039 winscard.c:283:SCardConnect() Error Reader Exclusive Feb 06 19:50:06 curie pcscd[3100]: 09673127 winscard.c:283:SCardConnect() Error Reader Exclusive Feb 06 19:51:25 curie pcscd[3100]: 78500770 winscard.c:283:SCardConnect() Error Reader Exclusive Feb 06 20:22:55 curie pcscd[3100]: 99999999 winscard.c:283:SCardConnect() Error Reader Exclusive Feb 06 20:23:00 curie pcscd[3100]: 04869977 winscard.c:283:SCardConnect() Error Reader Exclusive Feb 06 20:30:37 curie pcscd[3100]: 99999999 ccid_usb.c:797:WriteUSB() write failed (1/13): -4 LIBUSB_ERROR_NO_DEVICE Feb 07 20:55:56 curie systemd[1]: Started PC/SC Smart Card Daemon. Feb 07 20:55:56 curie pcscd[21376]: 00000000 ifdhandler.c:151:CreateChannelByNameOrChannel() failed Feb 07 20:55:56 curie pcscd[21376]: 00000012 readerfactory.c:1110:RFInitializeReader() Open Port 0x200000 Failed (usb:1050/0111:libudev:0:/dev/bus/usb/001/015) Feb 07 20:55:56 curie pcscd[21376]: 00000004 readerfactory.c:375:RFAddReader() Yubico Yubikey NEO OTP+CCID init failed. Feb 07 20:56:02 curie pcscd[21376]: 05648900 winscard.c:283:SCardConnect() Error Reader Exclusive Feb 07 20:56:12 curie pcscd[21376]: 09655699 winscard.c:283:SCardConnect() Error Reader Exclusive Feb 07 20:56:36 curie pcscd[21376]: 24217358 winscard.c:283:SCardConnect() Error Reader Exclusive Feb 07 21:06:59 curie pcscd[21376]: 99999999 winscard.c:283:SCardConnect() Error Reader Exclusive Feb 07 21:08:03 curie pcscd[21376]: 63425592 winscard.c:283:SCardConnect() Error Reader Exclusive Feb 07 22:01:33 curie pcscd[21376]: 99999999 winscard.c:283:SCardConnect() Error Reader Exclusive Feb 07 22:27:31 curie pcscd[21376]: 99999999 ccid_usb.c:797:WriteUSB() write failed (1/15): -4 LIBUSB_ERROR_NO_DEVICE Feb 08 10:12:36 curie systemd[1]: Started PC/SC Smart Card Daemon. Feb 08 10:12:36 curie pcscd[14439]: 00000000 ifdhandler.c:151:CreateChannelByNameOrChannel() failed Feb 08 10:12:36 curie pcscd[14439]: 00000014 readerfactory.c:1110:RFInitializeReader() Open Port 0x200000 Failed (usb:1050/0111:libudev:0:/dev/bus/usb/001/016) Feb 08 10:12:36 curie pcscd[14439]: 00000003 readerfactory.c:375:RFAddReader() Yubico Yubikey NEO OTP+CCID init failed. Feb 08 10:13:10 curie pcscd[14439]: 33826818 winscard.c:283:SCardConnect() Error Reader Exclusive Feb 08 10:17:53 curie pcscd[14439]: 99999999 ccid_usb.c:797:WriteUSB() write failed (1/16): -4 LIBUSB_ERROR_NO_DEVICE Feb 08 10:17:58 curie pcscd[14439]: 04993454 ifdhandler.c:151:CreateChannelByNameOrChannel() failed Feb 08 10:17:58 curie pcscd[14439]: 00000012 readerfactory.c:1110:RFInitializeReader() Open Port 0x200000 Failed (usb:1050/0111:libudev:0:/dev/bus/usb/001/017) Feb 08 10:17:58 curie pcscd[14439]: 00000004 readerfactory.c:375:RFAddReader() Yubico Yubikey NEO OTP+CCID init failed. Feb 08 10:18:11 curie pcscd[14439]: 12507788 winscard.c:283:SCardConnect() Error Reader Exclusive Feb 08 10:47:48 curie pcscd[14439]: 99999999 winscard.c:283:SCardConnect() Error Reader Exclusive Feb 08 11:00:00 curie pcscd[14439]: 99999999 winscard.c:283:SCardConnect() Error Reader Exclusive -- System Information: Debian Release: 9.0 APT prefers testing APT policy: (500, 'testing') Architecture: amd64 (x86_64) Kernel: Linux 4.9.0-1-amd64 (SMP w/4 CPU cores) Locale: LANG=fr_CA.UTF-8, LC_CTYPE=fr_CA.UTF-8 (charmap=UTF-8) Shell: /bin/sh linked to /usr/bin/dash Init: systemd (via /run/systemd/system) Versions of packages scdaemon depends on: ii gnupg-agent 2.1.18-3 ii libassuan0 2.4.3-2 ii libc6 2.24-9 ii libgcrypt20 1.7.6-1 ii libgpg-error0 1.26-2 ii libksba8 1.3.5-2 ii libnpth0 1.3-1 ii libusb-1.0-0 2:1.0.21-1 scdaemon recommends no packages. scdaemon suggests no packages. -- no debconf information
