Bug 1394501 - Flooded with 'WARN Event TRB for slot X ep Y with no TDs queued?' and pcscd messages with Yubikey 4
Summary: Flooded with 'WARN Event TRB for slot X ep Y with no TDs queued?' and pcscd m...
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: Fedora
Classification: Fedora
Component: kernel
Version: 27
Hardware: Unspecified
OS: Unspecified
unspecified
high
Target Milestone: ---
Assignee: Kernel Maintainer List
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2016-11-12 18:33 UTC by James
Modified: 2018-04-09 18:30 UTC (History)
10 users (show)

Fixed In Version:
Clone Of:
Environment:
Last Closed: 2018-04-09 18:30:08 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)

Description James 2016-11-12 18:33:03 UTC
Description of problem:
After a certain amount of idle time (it doesn't happen immediately after boot), plugging in a Yubikey 4 configured for both smartcard and OTP-via-HID functionality results in a flood of the form:

39616.503920] usb 2-5.5.2: new full-speed USB device number 14 using xhci_hcd
[39616.581731] usb 2-5.5.2: New USB device found, idVendor=1050, idProduct=0405
[39616.581735] usb 2-5.5.2: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[39616.581737] usb 2-5.5.2: Product: Yubikey 4 OTP+CCID
[39616.581738] usb 2-5.5.2: Manufacturer: Yubico
[39616.583880] input: Yubico Yubikey 4 OTP+CCID as /devices/pci0000:00/0000:00:14.0/usb2/2-5/2-5.5/2-5.5.2/2-5.5.2:1.0/0003:1050:0405.0009/input/input19
[39616.636301] hid-generic 0003:1050:0405.0009: input,hidraw5: USB HID v1.10 Keyboard [Yubico Yubikey 4 OTP+CCID] on usb-0000:00:14.0-5.5.2/input0
[39617.621511] xhci_hcd 0000:00:14.0: WARN Event TRB for slot 16 ep 4 with no TDs queued?
[39617.628193] xhci_hcd 0000:00:14.0: WARN Event TRB for slot 16 ep 4 with no TDs queued?
[39617.637363] xhci_hcd 0000:00:14.0: WARN Event TRB for slot 16 ep 4 with no TDs queued?


and so-on. This happens even with autosuspend=-1.

At the same time, pcscd floods the logs with:


Nov 12 18:22:28 kowalski.cb.ettle pcscd[2188]: 00000003 winscard.c:1643:SCardTransmit() Card not transacted: 0x80100016
Nov 12 18:22:28 kowalski.cb.ettle pcscd[2188]: 00006108 ccid_usb.c:783:WriteUSB() write failed (2/14): -9 LIBUSB_ERROR_PIPE
Nov 12 18:22:28 kowalski.cb.ettle pcscd[2188]: 00000008 ifdwrapper.c:548:IFDTransmit() Card not transacted: 612
Nov 12 18:22:28 kowalski.cb.ettle pcscd[2188]: 00000004 winscard.c:1643:SCardTransmit() Card not transacted: 0x80100016
Nov 12 18:22:28 kowalski.cb.ettle pcscd[2188]: 00002624 ccid_usb.c:783:WriteUSB() write failed (2/14): -9 LIBUSB_ERROR_PIPE
Nov 12 18:22:28 kowalski.cb.ettle pcscd[2188]: 00000009 ifdwrapper.c:548:IFDTransmit() Card not transacted: 612
Nov 12 18:22:28 kowalski.cb.ettle pcscd[2188]: 00000003 winscard.c:1643:SCardTransmit() Card not transacted: 0x80100016


and so-on. Otherwise the Yubikey seems accessible.

Doesn't matter if the Yubikey is plugged into a USB 2 or 3 port, directly or via a USB 2 or 3 hub.

00:14.0 USB controller: Intel Corporation Wildcat Point-LP USB xHCI Controller (rev 03)

Version-Release number of selected component (if applicable):
kernel-4.8.6-201.fc24.x86_64
pcsc-lite-1.8.17-2.fc24.x86_64

Comment 1 Justin M. Forbes 2017-04-11 14:59:31 UTC
*********** MASS BUG UPDATE **************

We apologize for the inconvenience.  There are a large number of bugs to go through and several of them have gone stale.  Due to this, we are doing a mass bug update across all of the Fedora 24 kernel bugs.

Fedora 25 has now been rebased to 4.10.9-100.fc24.  Please test this kernel update (or newer) and let us know if you issue has been resolved or if it is still present with the newer kernel.

If you have moved on to Fedora 26, and are still experiencing this issue, please change the version to Fedora 26.

If you experience different issues, please open a new bug report for those.

Comment 2 James 2017-04-13 23:56:27 UTC
Still present with 4.10.8-200.fc25.x86_64

Comment 3 Fedora End Of Life 2017-07-25 23:51:26 UTC
This message is a reminder that Fedora 24 is nearing its end of life.
Approximately 2 (two) weeks from now Fedora will stop maintaining
and issuing updates for Fedora 24. It is Fedora's policy to close all
bug reports from releases that are no longer maintained. At that time
this bug will be closed as EOL if it remains open with a Fedora  'version'
of '24'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version'
to a later Fedora version.

Thank you for reporting this issue and we are sorry that we were not
able to fix it before Fedora 24 is end of life. If you would still like
to see this bug fixed and are able to reproduce it against a later version
of Fedora, you are encouraged  change the 'version' to a later Fedora
version prior this bug is closed as described in the policy above.

Although we aim to fix as many bugs as possible during every release's
lifetime, sometimes those efforts are overtaken by events. Often a
more recent Fedora release includes newer upstream software that fixes
bugs or makes them obsolete.

Comment 4 Fedora End Of Life 2017-08-08 19:14:17 UTC
Fedora 24 changed to end-of-life (EOL) status on 2017-08-08. Fedora 24 is
no longer maintained, which means that it will not receive any further
security or bug fix updates. As a result we are closing this bug.

If you can reproduce this bug against a currently maintained version of
Fedora please feel free to reopen this bug against that version. If you
are unable to reopen this bug, please file a new report against the
current release. If you experience problems, please add a comment to this
bug.

Thank you for reporting this bug and we are sorry it could not be fixed.

Comment 5 Marc 2017-09-17 17:06:24 UTC
Same here, Fedora 25, 4.12.11-200.fc25.x86_64

After installing opensc ( opensc-0.16.0-2.20161016git0362439.fc25.x86_64 ) I started being spammed with similar messages in /var/log/messages when plugging in a yubikey 4. 
As the key is used for MFA web based I guess I am forced to use opensc in order to have a client certificate available from a security device in firefox.
Before installing opensc I did not see messages like

Sep 17 13:09:27 marchost kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 8 ep 4 with no TDs queued?
Sep 17 13:09:27 marchost kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 8 ep 4 with no TDs queued?
Sep 17 13:09:28 marchost kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 8 ep 4 with no TDs queued?
Sep 17 13:09:28 marchost kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 8 ep 4 with no TDs queued?
etc.

The sequence starts out with:

Sep 17 18:21:05 marchost kernel: usb 3-3: new full-speed USB device number 11 using xhci_hcd
Sep 17 18:21:05 marchost kernel: usb 3-3: New USB device found, idVendor=1050, idProduct=0407
Sep 17 18:21:05 marchost kernel: usb 3-3: New USB device strings: Mfr=1, Product=2, SerialNumber=0
Sep 17 18:21:05 marchost kernel: usb 3-3: Product: Yubikey 4 OTP+U2F+CCID
Sep 17 18:21:05 marchost kernel: usb 3-3: Manufacturer: Yubico
Sep 17 18:21:05 marchost kernel: input: Yubico Yubikey 4 OTP+U2F+CCID as /devices/pci0000:00/0000:00:14.0/usb3/3-3/3-3:1.0/0003:1050:0407.000B/input/input29
Sep 17 18:21:05 marchost kernel: hid-generic 0003:1050:0407.000B: input,hidraw0: USB HID v1.10 Keyboard [Yubico Yubikey 4 OTP+U2F+CCID] on usb-0000:00:14.0-3/input0
Sep 17 18:21:05 marchost kernel: hid-generic 0003:1050:0407.000C: hiddev96,hidraw1: USB HID v1.10 Device [Yubico Yubikey 4 OTP+U2F+CCID] on usb-0000:00:14.0-3/input1
Sep 17 18:21:05 marchost mtp-probe[13115]: checking bus 3, device 11: "/sys/devices/pci0000:00/0000:00:14.0/usb3/3-3"
Sep 17 18:21:05 marchost mtp-probe[13115]: bus: 3, device: 11 was not an MTP device
Sep 17 18:21:05 marchost pcscd[13012]: 00000000 ifdhandler.c:151:CreateChannelByNameOrChannel() failed
Sep 17 18:21:05 marchost pcscd[13012]: 00000235 readerfactory.c:1110:RFInitializeReader() Open Port 0x200000 Failed (usb:1050/0407:libudev:0:/dev/bus/usb/003/011)
Sep 17 18:21:05 marchost pcscd[13012]: 00000120 readerfactory.c:375:RFAddReader() Yubico Yubikey 4 OTP+U2F+CCID init failed.
Sep 17 18:21:05 marchost pcscd[13012]: 00024518 ifdhandler.c:151:CreateChannelByNameOrChannel() failed
Sep 17 18:21:05 marchost pcscd[13012]: 00000009 readerfactory.c:1110:RFInitializeReader() Open Port 0x200001 Failed (usb:1050/0407:libudev:1:/dev/bus/usb/003/011)
Sep 17 18:21:05 marchost pcscd[13012]: 00000002 readerfactory.c:375:RFAddReader() Yubico Yubikey 4 OTP+U2F+CCID init failed.
Sep 17 18:21:06 marchost kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 10 ep 4 with no TDs queued?
Sep 17 18:21:06 marchost kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 10 ep 4 with no TDs queued?
Sep 17 18:21:06 marchost kernel: xhci_hcd 0000:00:14.0: WARN Event TRB for slot 10 ep 4 with no TDs queued?
...

Comment 6 Marc 2017-09-18 06:04:06 UTC
after erasing package opensc I still see the same pcscd messages at insert of key:

Sep 18 07:58:58 marchost pcscd[2601]: 00000000 ifdhandler.c:151:CreateChannelByNameOrChannel() failed
Sep 18 07:58:58 marchost pcscd[2601]: 00000019 readerfactory.c:1110:RFInitializeReader() Open Port 0x200000 Failed (usb:1050/0407:libudev:0:/dev/bus/usb/003/004)
Sep 18 07:58:58 marchost pcscd[2601]: 00000002 readerfactory.c:375:RFAddReader() Yubico Yubikey 4 OTP+U2F+CCID init failed.
Sep 18 07:58:58 marchost pcscd[2601]: 00002297 ifdhandler.c:151:CreateChannelByNameOrChannel() failed
Sep 18 07:58:58 marchost pcscd[2601]: 00000004 readerfactory.c:1110:RFInitializeReader() Open Port 0x200000 Failed (usb:1050/0407:libudev:1:/dev/bus/usb/003/004)
Sep 18 07:58:58 marchost pcscd[2601]: 00000002 readerfactory.c:375:RFAddReader() Yubico Yubikey 4 OTP+U2F+CCID init failed.

The xhci_hcd messages only appear when interacting with the device by means of yubico-piv-tool. opensc looks to be interacting continuously with the key.

Comment 7 Orion Poplawski 2018-01-11 23:00:39 UTC
Seems a dup of bug #959699

Comment 8 James 2018-01-13 01:27:18 UTC
I only see this on my machines with Intel controllers. Never seen it with Renesas.

Comment 9 Laura Abbott 2018-02-20 20:02:03 UTC
We apologize for the inconvenience.  There is a large number of bugs to go through and several of them have gone stale.  As kernel maintainers, we try to keep up with bugzilla but due the rate at which the upstream kernel project moves, bugs may be fixed without any indication to us. Due to this, we are doing a mass bug update across all of the Fedora 27 kernel bugs.
 
Fedora 27 has now been rebased to 4.15.3-300.f27.  Please test this kernel update (or newer) and let us know if you issue has been resolved or if it is still present with the newer kernel.
 
If you experience different issues, please open a new bug report for those.

Comment 10 James 2018-03-11 21:45:20 UTC
Not seen this on 4.15.4-300.fc27.x86_64 after 15 days' uptime. Will keep open for a bit longer before considering it fixed.

Comment 11 James 2018-04-09 18:30:08 UTC
seems fixed in kernel-4.15.14-300.fc27.x86_64


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