Bug#931462: pcscd: Hangs after a ykman info
Le 05/07/2019 à 16:56, Julien Palard a écrit : Hello Ludovic, It could be interesting to have a pcscd log as documented athttps://pcsclite.apdu.fr/#support Here are the requested infos: $ ykman info Device type: YubiKey 4 [...] Firmware version: 4.3.5 Enabled USB interfaces: OTP+FIDO+CCID Applications OTP Enabled FIDO U2FEnabled OpenPGP Enabled PIV Enabled OATHEnabled FIDO2 Not available $ /usr/sbin/pcscd --version pcsc-lite version 1.8.25. Copyright (C) 1999-2002 by David Corcoran . Copyright (C) 2001-2018 by Ludovic Rousseau . Copyright (C) 2003-2004 by Damien Sauveron . Report bugs to . Enabled features: Linux x86_64-pc-linux-gnu libsystemd serial usb libudev usbdropdir=/usr/lib/pcsc/drivers ipcdir=/var/run/pcscd configdir=/etc/reader.conf.d $ lsb_release -a No LSB modules are available. Distributor ID: Debian Description:Debian GNU/Linux 10 (buster) Release:10 Codename: buster $ lsusb | grep -i yubi Bus 003 Device 030: ID 1050:0407 Yubico.com Yubikey 4 OTP+U2F+CCID logs attached where I ran the following sequence: mdk@lighthaven$ ssh-add -e /usr/lib/x86_64-linux-gnu/opensc-pkcs11.so; ssh-add -s /usr/lib/x86_64-linux-gnu/opensc-pkcs11.so Card removed: /usr/lib/x86_64-linux-gnu/opensc-pkcs11.so Enter passphrase for PKCS#11: Card added: /usr/lib/x86_64-linux-gnu/opensc-pkcs11.so 0012 [140528082081536] APDU: 00 CB 3F FF 03 5C 01 7E 00 0009 [140528082081536] ifdhandler.c:1303:IFDHTransmitToICC() usb:1050/0407:libudev:2:/dev/bus/usb/003/030 (lun: 0) 0008 [140528082081536] commands.c:1623:CmdXfrBlockAPDU_extended() T=0 (extended): 9 bytes 0017 [140528082081536] -> 00 6F 09 00 00 00 00 31 00 00 00 00 CB 3F FF 03 5C 01 7E 00 0298 [140528082081536] <- 00 81 00 00 00 00 00 31 40 FC 00 0011 [140528082081536] commands.c:1523:CCID_Receive Overrun error 0006 [140528082081536] SW: 0007 [140528082081536] ifdwrapper.c:543:IFDTransmit() Card not transacted: 612 0007 [140528082081536] winscard.c:1620:SCardTransmit() Card not transacted: 0x80100016 The reader reports an error 0xFC Overrun error. According to the CCID specification it is "Overrun error while talking to the ICC". ICC is the smart card. In your case it is the chip inside the token. I have no idea why the token reports such an error. I reader firmware issue? The problem is not with pscsd. I am not sure I can help here. You can try to report the problem on OpenSC-devel mailing list. Maybe someone with YubiKey experience can help. https://github.com/OpenSC/OpenSC/wiki/Mailing-lists Bye -- Dr. Ludovic Rousseau
Bug#931462: pcscd: Hangs after a ykman info
Hello Ludovic, > It could be interesting to have a pcscd log as documented > athttps://pcsclite.apdu.fr/#support Here are the requested infos: $ ykman info Device type: YubiKey 4 [...] Firmware version: 4.3.5 Enabled USB interfaces: OTP+FIDO+CCID Applications OTP Enabled FIDO U2FEnabled OpenPGP Enabled PIV Enabled OATHEnabled FIDO2 Not available $ /usr/sbin/pcscd --version pcsc-lite version 1.8.25. Copyright (C) 1999-2002 by David Corcoran . Copyright (C) 2001-2018 by Ludovic Rousseau . Copyright (C) 2003-2004 by Damien Sauveron . Report bugs to . Enabled features: Linux x86_64-pc-linux-gnu libsystemd serial usb libudev usbdropdir=/usr/lib/pcsc/drivers ipcdir=/var/run/pcscd configdir=/etc/reader.conf.d $ lsb_release -a No LSB modules are available. Distributor ID: Debian Description:Debian GNU/Linux 10 (buster) Release:10 Codename: buster $ lsusb | grep -i yubi Bus 003 Device 030: ID 1050:0407 Yubico.com Yubikey 4 OTP+U2F+CCID logs attached where I ran the following sequence: mdk@lighthaven$ ssh-add -e /usr/lib/x86_64-linux-gnu/opensc-pkcs11.so; ssh-add -s /usr/lib/x86_64-linux-gnu/opensc-pkcs11.so Card removed: /usr/lib/x86_64-linux-gnu/opensc-pkcs11.so Enter passphrase for PKCS#11: Card added: /usr/lib/x86_64-linux-gnu/opensc-pkcs11.so mdk@lighthaven$ ssh mdk.fr hostname mdk.fr mdk@lighthaven$ ykman info Device type: YubiKey 4 Serial number: 5651488 Firmware version: 4.3.5 Enabled USB interfaces: OTP+FIDO+CCID Applications OTP Enabled FIDO U2FEnabled OpenPGP Enabled PIV Enabled OATHEnabled FIDO2 Not available mdk@lighthaven$ ssh mdk.fr hostname sign_and_send_pubkey: signing failed: agent refused operation m...@mdk.fr: Permission denied (publickey). Don't hesitate if you need me to run any more tests, I'm also available on freenode I'm mdk. Bests, -- Julien Palard https://mdk.fr debuglog.c:299:DebugLogSetLevel() debug level=debug 0012 debuglog.c:320:DebugLogSetCategory() Debug options: APDU [36m0003[0m [140528118052800] [34mpcscdaemon.c:352:main() Force colored logs[0m [36m0025[0m [140528118052800] [01;31mutils.c:82:GetDaemonPid() Can't open /var/run/pcscd/pcscd.pid: No such file or directory[0m [36m0068[0m [140528118052800] configfile.l:284:DBGetReaderListDir() Parsing conf directory: /etc/reader.conf.d [36m0011[0m [140528118052800] configfile.l:360:DBGetReaderList() Parsing conf file: /etc/reader.conf.d/libccidtwin [36m0239[0m [140528118052800] configfile.l:321:DBGetReaderListDir() Skipping non regular file: .. [36m0006[0m [140528118052800] configfile.l:321:DBGetReaderListDir() Skipping non regular file: . [36m0005[0m [140528118052800] [34mpcscdaemon.c:662:main() pcsc-lite 1.8.25 daemon ready.[0m [36m4120[0m [140528118052800] hotplug_libudev.c:301:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/001/001 [36m0109[0m [140528118052800] hotplug_libudev.c:301:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/001/001 [36m0113[0m [140528118052800] hotplug_libudev.c:301:get_driver() Looking for a driver for VID: 0x045E, PID: 0x00CB, path: /dev/bus/usb/001/003 [36m0100[0m [140528118052800] hotplug_libudev.c:301:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/001/001 [36m0109[0m [140528118052800] hotplug_libudev.c:301:get_driver() Looking for a driver for VID: 0x13D3, PID: 0x3414, path: /dev/bus/usb/001/002 [36m0109[0m [140528118052800] hotplug_libudev.c:301:get_driver() Looking for a driver for VID: 0x13D3, PID: 0x3414, path: /dev/bus/usb/001/002 [36m0169[0m [140528118052800] hotplug_libudev.c:301:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0003, path: /dev/bus/usb/002/001 [36m0205[0m [140528118052800] hotplug_libudev.c:301:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/003/001 [36m0109[0m [140528118052800] hotplug_libudev.c:301:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/003/001 [36m0116[0m [140528118052800] hotplug_libudev.c:301:get_driver() Looking for a driver for VID: 0x13BA, PID: 0x0018, path: /dev/bus/usb/003/002 [36m0113[0m [140528118052800] hotplug_libudev.c:301:get_driver() Looking for a driver for VID: 0x13BA, PID: 0x0018, path: /dev/bus/usb/003/002 [36m0106[0m [140528118052800] hotplug_libudev.c:301:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/003/001 [36m0115[0m [140528118052800] hotplug_libudev.c:301:get_driver() Looking for a driver for VID: 0x05E3, PID: 0x0610, path: /dev/bus/usb/003/003 [36m0154[0m [140528118052800] hotplug_libudev.c:301:get_driver() Looking for a driver for VID: 0x1050, PID: 0x0407, path: /dev/bus/usb/003/030 [36m0006[0m [14
Bug#931462: pcscd: Hangs after a ykman info
Hello Julien,
Le 05/07/2019 à 15:17, Julien Palard a écrit :
Package: pcscd
Version: 1.8.25-1
Severity: normal
When I use the following sequence of commands:
$ ssh-add -s /usr/lib/x86_64-linux-gnu/opensc-pkcs11.so
$ ssh remote_host hostname
$ ykman info
$ ssh remote_host hostname
the 2nd ssh won't work, I'll get: sign_and_send_pubkey: signing
failed: agent refused operation
If I run ykman info afterwards, it freezes.
I tried stracing pcscd a bit and found it waiting indefinitly in a
nanosleep loop (strace start during a ykman info, before it freezes,
so you have a bit of context):
[pid 14245] accept(3, {sa_family=AF_UNIX}, [110->2]) = 16
[pid 14245] clone(strace: Process 14801 attached
child_stack=0x7f0bd161df30,
flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID\
, parent_tidptr=0x7f0bd161e9d0, tls=0x7f0bd161e700,
child_tidptr=0x7f0bd161e9d0) = 14801
[pid 14801] set_robust_list(0x7f0bd161e9e0, 24
[pid 14245] alarm(0
[pid 14801] <... set_robust_list resumed> ) = 0
[pid 14245] <... alarm resumed> ) = 0
[pid 14801] read(16, "\f\0\0\0\21\0\0\0", 8) = 8
[pid 14801] read(16, "\4\0\0\0\4\0\0\0\0\0\0\0", 12) = 12
[pid 14801] sendto(16, "\4\0\0\0\4\0\0\0\0\0\0\0", 12, MSG_NOSIGNAL, NULL, 0) =
12
[pid 14801] read(16, "\f\0\0\0\1\0\0\0", 8) = 8
[pid 14801] read(16, "\0\0\0\0\0\0\0\0\0\0\0\0", 12) = 12
[pid 14801] sendto(16, "\0\0\0\0f*Y?\0\0\0\0", 12, MSG_NOSIGNAL, NULL, 0) = 12
[pid 14801] read(16, "\230\0\0\0\4\0\0\0", 8) = 8
[pid 14801] read(16, "f*Y?Yubico YubiKey OTP+FIDO+CCID"..., 152) = 152
[pid 14801] nanosleep({tv_sec=0, tv_nsec=1}, NULL) = 0
[pid 14801] nanosleep({tv_sec=0, tv_nsec=1}, NULL) = 0
[pid 14801] nanosleep({tv_sec=0, tv_nsec=1}, NULL) = 0
[pid 14801] nanosleep({tv_sec=0, tv_nsec=1}, NULL) = 0
[pid 14801] nanosleep({tv_sec=0, tv_nsec=1}, NULL) = 0
[pid 14801] nanosleep({tv_sec=0, tv_nsec=1}, NULL) = 0
(at vitam eternam)
Strage thing: there is not a single ioctl during the freez, so I bet
the nanosleep is here to wait for a previous ioctl reply. The process
being waited is the one calling ioctl USBDEVFS_REAPURBNDELAY and it
looks waiting for a poll([{fd=10, events=POLLIN}, {fd=12,
events=POLLIN}, {fd=13, events=POLLOUT}], 3, 6 13
being the fd for the Yubikey.
When this process does a poll it typically get a ([{fd=13,
revents=POLLOUT}]) almost immediatly (I did not straced with timings
though).
Running:
ssh-add -e /usr/lib/x86_64-linux-gnu/opensc-pkcs11.so
stops the nanosleep loop and everything works again, I do not need to
unplug-replug the key. I tried with two distinct Yubikey 4, one a bit
old and one almost new.
During the ssh failure I see:
[pid 16285] write(1, "03008905 ccid_usb.c:898:ReadUSB() read failed (2/3): -7
LIBUSB_ERROR_TIMEOUT\n", 77) = 77
[pid 16285] write(1, "0123 ifdwrapper.c:543:IFDTransmit() Card not transacted:
612\n", 65) = 65
[pid 16285] write(1, "0092 winscard.c:1626:SCardTransmit() Card not transacted:
0x80100016\n", 73) = 73
Tell me if you're interested in my digging more deeply.
It could be interesting to have a pcscd log as documented at
https://pcsclite.apdu.fr/#support
Thanks
--
Dr. Ludovic Rousseau
Bug#931462: pcscd: Hangs after a ykman info
Package: pcscd
Version: 1.8.25-1
Severity: normal
When I use the following sequence of commands:
$ ssh-add -s /usr/lib/x86_64-linux-gnu/opensc-pkcs11.so
$ ssh remote_host hostname
$ ykman info
$ ssh remote_host hostname
the 2nd ssh won't work, I'll get: sign_and_send_pubkey: signing
failed: agent refused operation
If I run ykman info afterwards, it freezes.
I tried stracing pcscd a bit and found it waiting indefinitly in a
nanosleep loop (strace start during a ykman info, before it freezes,
so you have a bit of context):
[pid 14245] accept(3, {sa_family=AF_UNIX}, [110->2]) = 16
[pid 14245] clone(strace: Process 14801 attached
child_stack=0x7f0bd161df30,
flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID\
, parent_tidptr=0x7f0bd161e9d0, tls=0x7f0bd161e700,
child_tidptr=0x7f0bd161e9d0) = 14801
[pid 14801] set_robust_list(0x7f0bd161e9e0, 24
[pid 14245] alarm(0
[pid 14801] <... set_robust_list resumed> ) = 0
[pid 14245] <... alarm resumed> ) = 0
[pid 14801] read(16, "\f\0\0\0\21\0\0\0", 8) = 8
[pid 14801] read(16, "\4\0\0\0\4\0\0\0\0\0\0\0", 12) = 12
[pid 14801] sendto(16, "\4\0\0\0\4\0\0\0\0\0\0\0", 12, MSG_NOSIGNAL, NULL, 0) =
12
[pid 14801] read(16, "\f\0\0\0\1\0\0\0", 8) = 8
[pid 14801] read(16, "\0\0\0\0\0\0\0\0\0\0\0\0", 12) = 12
[pid 14801] sendto(16, "\0\0\0\0f*Y?\0\0\0\0", 12, MSG_NOSIGNAL, NULL, 0) = 12
[pid 14801] read(16, "\230\0\0\0\4\0\0\0", 8) = 8
[pid 14801] read(16, "f*Y?Yubico YubiKey OTP+FIDO+CCID"..., 152) = 152
[pid 14801] nanosleep({tv_sec=0, tv_nsec=1}, NULL) = 0
[pid 14801] nanosleep({tv_sec=0, tv_nsec=1}, NULL) = 0
[pid 14801] nanosleep({tv_sec=0, tv_nsec=1}, NULL) = 0
[pid 14801] nanosleep({tv_sec=0, tv_nsec=1}, NULL) = 0
[pid 14801] nanosleep({tv_sec=0, tv_nsec=1}, NULL) = 0
[pid 14801] nanosleep({tv_sec=0, tv_nsec=1}, NULL) = 0
(at vitam eternam)
Strage thing: there is not a single ioctl during the freez, so I bet
the nanosleep is here to wait for a previous ioctl reply. The process
being waited is the one calling ioctl USBDEVFS_REAPURBNDELAY and it
looks waiting for a poll([{fd=10, events=POLLIN}, {fd=12,
events=POLLIN}, {fd=13, events=POLLOUT}], 3, 6 13
being the fd for the Yubikey.
When this process does a poll it typically get a ([{fd=13,
revents=POLLOUT}]) almost immediatly (I did not straced with timings
though).
Running:
ssh-add -e /usr/lib/x86_64-linux-gnu/opensc-pkcs11.so
stops the nanosleep loop and everything works again, I do not need to
unplug-replug the key. I tried with two distinct Yubikey 4, one a bit
old and one almost new.
During the ssh failure I see:
[pid 16285] write(1, "03008905 ccid_usb.c:898:ReadUSB() read failed (2/3): -7
LIBUSB_ERROR_TIMEOUT\n", 77) = 77
[pid 16285] write(1, "0123 ifdwrapper.c:543:IFDTransmit() Card not
transacted: 612\n", 65) = 65
[pid 16285] write(1, "0092 winscard.c:1626:SCardTransmit() Card not
transacted: 0x80100016\n", 73) = 73
Tell me if you're interested in my digging more deeply.
-- System Information:
Debian Release: 10.0
APT prefers testing
APT policy: (900, 'testing'), (200, 'unstable')
Architecture: amd64 (x86_64)
Kernel: Linux 4.19.0-4-amd64 (SMP w/8 CPU cores)
Kernel taint flags: TAINT_PROPRIETARY_MODULE, TAINT_OOT_MODULE,
TAINT_UNSIGNED_MODULE
Locale: LANG=en_US.UTF-8, LC_CTYPE=en_US.UTF-8 (charmap=UTF-8) (ignored: LC_ALL
set to en_US.utf8), LANGUAGE=en_US.UTF-8 (charmap=UTF-8) (ignored: LC_ALL set
to en_US.utf8)
Shell: /bin/sh linked to /usr/bin/dash
Init: systemd (via /run/systemd/system)
LSM: AppArmor: enabled
Versions of packages pcscd depends on:
ii libc6 2.28-10
ii libccid [pcsc-ifd-handler] 1.4.30-1
ii libpcsclite11.8.25-1
ii libsystemd0 241-5
ii libudev1241-5
ii lsb-base10.2019051400
pcscd recommends no packages.
Versions of packages pcscd suggests:
ii systemd 241-5
-- no debconf information
