Reader disconnects are noisy in journal/logs

[Jakuje]

Versions

• smart card reader driver name and version: pcsc-lite-ccid-1.4.34-1.fc34.x86_64
• pcsc-lite version: 1.9.1-1.fc34
• the output of the command /usr/sbin/pcscd --version:

pcsc-lite version 1.9.1.
Copyright (C) 1999-2002 by David Corcoran <[email protected]>.
Copyright (C) 2001-2018 by Ludovic Rousseau <[email protected]>.
Copyright (C) 2003-2004 by Damien Sauveron <[email protected]>.
Report bugs to <[email protected]>.
Enabled features: Linux x86_64-redhat-linux-gnu libsystemd serial usb libudev usbdropdir=/usr/lib64/pcsc/drivers ipcdir=/run/pcscd filter configdir=/etc/reader.conf.d

Platform

• Operating system or GNU/Linux distribution name and version: Fedora 34
• Smart card middleware name and version: Probably OpenSC
• Smart card reader manufacturer name and reader model name: Alcor Micro AU9540 00 00
• Smart card name: Should not be relevant

Log

oct 06 05:03:29 user pcscd[52231]: 00400073 ccid_usb.c:858:WriteUSB() write failed (3/4): -4 LIBUSB_ERROR_NO_DEVICE
oct 06 05:03:29 user pcscd[52231]: 00000010 ifdwrapper.c:364:IFDStatusICC() Card not transacted: 617
oct 06 05:03:30 user pcscd[52231]: 01000094 eventhandler.c:336:EHStatusHandlerThread() Error communicating to: Alcor Micro AU9540 00 00
oct 06 05:03:30 user pcscd[52231]: 00000056 ccid_usb.c:1343:InterruptRead() libusb_submit_transfer failed: LIBUSB_ERROR_NO_DEVICE
oct 06 05:03:31 user pcscd[52231]: 00400082 ccid_usb.c:858:WriteUSB() write failed (3/4): -4 LIBUSB_ERROR_NO_DEVICE
oct 06 05:03:31 user pcscd[52231]: 00000010 ifdwrapper.c:364:IFDStatusICC() Card not transacted: 617

We have the following bug reported that the above logs show repetitively when smart card reader is disconnected. This might be the case for disconnecting a reader, undocking a computer or removing a USB token.

The questions would be:

• when we got error "Card not transacted", should the pcsc try over?
• When we got NO_DEVICE error (right, this is from CCID, but I wanted to avoid duplicating error report there too), should not CCID stop until it will get information the (new?) device is ready?
• If these are expected, should these logs be less verbose than ERRORs?

https://bugzilla.redhat.com/show_bug.cgi?id=2011128

[LudovicRousseau]

I can reproduce the problem.
A more complete log is:

04147530 [139928564864576] hotplug_libudev.c:661:HPEstablishUSBNotifications() USB Device removed
00000123 [139928564864576] hotplug_libudev.c:367:HPRemoveDevice() Removing USB device[0]: Gemalto PC Twin Reader at /dev/bus/usb/001/003
00000007 [139928564864576] readerfactory.c:614:RFRemoveReader() UnrefReader() count was: 1
00000003 [139928564864576] eventhandler.c:175:EHDestroyEventHandler() Stomping thread.
00000003 [139928564864576] ifdhandler.c:388:IFDHGetCapabilities() tag: 0xFB1, usb:08e6/3437:libudev:0:/dev/bus/usb/001/003 (lun: 0)
00000002 [139928564864576] ifdhandler.c:388:IFDHGetCapabilities() tag: 0xFB2, usb:08e6/3437:libudev:0:/dev/bus/usb/001/003 (lun: 0)
00000002 [139928564864576] eventhandler.c:200:EHDestroyEventHandler() Request stopping of polling thread
00000002 [139928564864576] ifdhandler.c:353:IFDHStopPolling() usb:08e6/3437:libudev:0:/dev/bus/usb/001/003 (lun: 0)
00399866 [139928547833408] ccid_usb.c:863:WriteUSB() write failed (1/3): -4 LIBUSB_ERROR_NO_DEVICE
00000014 [139928547833408] ifdwrapper.c:364:IFDStatusICC() Card not transacted: 617
00000020 [139928547833408] utils.c:98:SendHotplugSignal() Send hotplug signal to pcscd (pid=3589)
00000121 [139928573257280] pcscdaemon.c:193:signal_thread() Received signal: 10
01033669 [139928547833408] eventhandler.c:482:EHStatusHandlerThread() powerState: POWER_STATE_UNPOWERED
00000018 [139928547833408] eventhandler.c:504:EHStatusHandlerThread() Die
00000219 [139928564864576] eventhandler.c:215:EHDestroyEventHandler() Thread stomped.
00000012 [139928564864576] readerfactory.c:1133:RFUnInitializeReader() Attempting shutdown of Gemalto PC Twin Reader 00 00.
00000004 [139928564864576] ifdhandler.c:291:IFDHCloseChannel() usb:08e6/3437:libudev:0:/dev/bus/usb/001/003 (lun: 0)
00000014 [139928564864576] ccid_usb.c:863:WriteUSB() write failed (1/3): -4 LIBUSB_ERROR_NO_DEVICE
00000018 [139928564864576] ccid_usb.c:189:close_libusb_if_needed() libusb_exit
00000049 [139928564864576] readerfactory.c:991:RFUnloadReader() Unloading reader driver.

Since pcscd has been notified by libudev that the reader has been removed then there is no reason to try to talk to the reader again.

I will work on a fix.

[LudovicRousseau]

The problem should now be fixed with the git versions of PCSC and CCID.

On the original RedHat bug report I see "Every second 2 messages appear in logs, they keep appearing until the daemon is restarted".
This is a different problem. It looks like pcscd does NOT detect the reader removal and continue trying to talk to the reader.
Can you reproduce this problem?

[Jakuje]

Thank you for having a look into that. I do not have that particular reader and and I was not able to reproduce it with other plugging in and out for several times.

So most I can do is asking the original reporter with a scratch build of pcsc-lite and ccid with your fixes. Let me put the builds together.

[LudovicRousseau]

OK. We will see what Santiago Gala gets with the updated packages.

[sgala]

I get the same behaviour. Apparently it is not so much a matter of me unplugging the reader, but of me undocking the laptop, when the reader is in the dock. Undocking kills the USB hubs in a bad way (but this is a separate bug).

I will try later both the unplugging of the reader and the undocking with pcscd started in the foreground and logging.

[LudovicRousseau]

I also think it is a problem with the dock.
Can you run the command udevadm monitor--property then dock and undock the laptop.
I guess some events are not seen or reported by libudev.

What laptop and dock do you use?

In your case I would suggest to build pcsc-lite using --disable-libudev to use libusb instead of libudev. pcscd will continuously rescan the USB bus and should be able to detect removed readers.
It is not a fix but a way to avoid filling your disk with logs.

[LudovicRousseau]

@sgala I need you feedback to understand (and possibly fix) the problem.
Please help me and answer to my questions above.

[sgala]

Sorry, I got overwhelmed with work. The situation is:

• the problem is linked to the dock not handling properly the 2 usb hubs on it when docked/undocked
• possibly it is a BIOS (dock bios or ACPI bios) problem, as I have seen both Windows and Linux behave the same (USB-C hubs are only visible if thunderbolt undock/dock happens while the machine is suspended).
• I unplugged the card reader as it was giving this log spam most of the times I unplugged and I use it rarely, so now I have to plug it when I want to use it and take care of the problem after unplugging it.

I'm running packages that were suggested to fix the problem, but the problem is still there (I got a bit lost with the suggestions so I'm not sure if this is what I'm expected to be running):

$ dnf list pcsc-lite pcsc-lite-libs pcsc-lite-ccid pcsc-perl pcsc-tools
Last metadata expiration check: 0:01:17 ago on lun 08 nov 2021 16:05:59.
Installed Packages
pcsc-lite.x86_64                       1.9.4-1.fc34                    @copr:copr.fedorainfracloud.org:jjelen:pcsc-lite-future
pcsc-lite-ccid.x86_64                  1.4.36-1.fc34                   @copr:copr.fedorainfracloud.org:jjelen:pcsc-lite-future
pcsc-lite-libs.x86_64                  1.9.4-1.fc34                    @copr:copr.fedorainfracloud.org:jjelen:pcsc-lite-future
pcsc-perl.x86_64                       1.4.14-16.fc34                  @fedora                                                
pcsc-tools.x86_64                      1.5.7-3.fc34                    @fedora                                                
Available Packages
pcsc-lite.src                          1.9.4-1.fc34                    copr:copr.fedorainfracloud.org:jjelen:pcsc-lite-future 
pcsc-lite-ccid.src                     1.4.36-1.fc34                   copr:copr.fedorainfracloud.org:jjelen:pcsc-lite-future 
pcsc-lite-libs.i686                    1.9.1-1.fc34                    fedora    

Tell me specific, concrete actions that are not too time consuming to check the problem and I'll try them.

[LudovicRousseau]

• What laptop and dock models do you use?

1. connect the smart card reader to the dock
2. start the command udevadm monitor --property
3. then dock the laptop
4. and undock the laptop
5. stop the udevadm command
6. send me the generated output

[sgala]

Laptop is a "P1 Gen 3 (type 20TH, 20TJ ) Laptop (ThinkPad) - Type 20TJ " (according to Lenovo)
Dock is tricky, they list scores of models. I think it is a: https://support.lenovo.com/us/en/solutions/PD500252 ThinkPad Thunderbolt 3 Workstation Dock (230W)
The cable is not exactly the same, but it has both a power and a USB-C connector, which is very characteristic. Labelled as 230W.

I sent the files in a separate comment

[sgala]

Re: the output of udevadm monitor --property:

• docking and undocking without suspending (monitor.txt). Note that, while thunderbolt and display port work apparently well, the usb-c ports don't get enumerated this way, no diveces appear.
  monitor.txt

So I sent also same but suspending/waking up (twice, to get usb enumerated) in next message

[sgala]

Now, the same process but I: start monitoring, suspend, dock, wakeup, check that usb ports are enumerated, suspend, undock, wakeup, stop monitor -> monitor-suspending.txt

[LudovicRousseau]

@sgala your Alcor Micro AU9560 reader is connected on the USB-C port on the dock station?
I guess the reader is a USB-A and you have a USB-A to USB-C adaptor. Exact?

When you dock the laptop the USB-C port (of the dock) is NOT enumerated? Even if you connect a USB device after docking the laptop?

Can you generate a new trace:

1. start udevadm monitor --property
2. connect the USB reader
3. disconnect the USB reader

I would like to compare the events of a "normal" plug/unplug with what you have when you use the dock and suspend/resume.

[sgala]

This monitor.log trace corresponds to the plugging and unplugging of the reader with the dock already on. This works normally as the hub does not disappear in the middle... :)

[sgala]

I guess the reader is a USB-A and you have a USB-A to USB-C adaptor. Exact?

The reader is USB-A, but it is the dock that offers a number of USB-A ports. Not sure how.

And no, when I dock the laptop the usb-c or usb-a ports are invisible (hubs 3 and 4 are not there, neither anything in them, in lsubs --tree) until I authorise the dock AND THEN suspend and wake up again. If I set up the BIOS for automated auth of thunderbolt, I still need to unplug AND plug while suspended for the USB-C ports to be seen.

I only see in dmesg the "undocked" ACPI event appear, no matter if I dock or undock, I'm thinking about a bug in acpi bios, module or kernel.

[LudovicRousseau]

I contacted Lenovo and they said they were working on a similar problem reported by RedHat. I guess that is this issue.

As I already proposed in a previous message:

In your case I would suggest to ./configure pcsc-lite using --disable-libudev to use libusb instead of libudev. pcscd will continuously rescan the USB bus and should be able to detect removed readers.
It is not a fix but a way to avoid filling your disk with logs.

This will not fix the problem with the dock but pcscd should detect when the reader is "removed".

[sgala]

As I don't use often the reader I opted by disconnecting it from the dock. Now I will connect the reader and disconnect it either to laptop or to dock, but disconnecting the reader with the dock connected I don't have the problem with the log spam and battery drain

[LudovicRousseau]

Thanks for the feedback @sgala.
As I think your issue is related to the dock itself (or the laptop firmware) I can't fix it in PCSC.
I close this issue.

[sgala]

Thank you for your effort and sorry for the noise, when I started the bug I had not a clear idea about how broken is either the laptop firmware or the dock firmware. I'm leaning towards a laptop firmware / acpi problem.