Excessive CPU utilization

This is what I've got installed ^^

c@mawhrin-skel:~/omnibus-layers$ dpkg -l | grep pcscd
ii pcscd 1.8.14-1ubuntu1 amd64 Middleware to access a smart card using PC/SC (daemon side)

It looks like https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=812087

Can you rebuild pcscd with hotplug debug enabled. No need to install pcscd so you can't break your installation.

1. Get the source code of pcsc-lite, for example from https://alioth.debian.org/frs/?group_id=30105&release_id=2019#pcsclite-_1.8.15-title-content

2. install the build dependencies using:
$ sudo apt-get build-dep pcscd

3. edit the file PCSC/src/hotplug_libudev.c and change the line 66 from
#undef DEBUG_HOTPLUG
to
#define DEBUG_HOTPLUG

4. configure pcsc-lite using "./configure"

5. run pcscd using:
$ sudo ./src/pcscd -dfa

6. try to reproduce the 100% CPU consumption problem

This may generate a lot of logs if the problem is with libudev.

I ran pcscd as you suggested, capturing output. Made sure the smart card was working by using my SSH key. I was then able to reproduce the 100% cpu condition by plugging in my Logitech USB webcam.

Attached the output, but I redacted the hex dumps before posting here because I'm not sure if they contain sensitive information. Let me know if you need the original.

Does your log trace include the moment when pcscd consumed 100% of CPU?

I ask because I could not find anything strange in the trace.

It starts consuming 100% CPU after this:

02341452 hotplug_libudev.c:642:HPEstablishUSBNotifications() USB Device removed
00000217 hotplug_libudev.c:619:HPEstablishUSBNotifications()
00000068 hotplug_libudev.c:642:HPEstablishUSBNotifications() USB Device removed
00000149 hotplug_libudev.c:619:HPEstablishUSBNotifications()
00002713 hotplug_libudev.c:642:HPEstablishUSBNotifications() USB Device removed
00000152 hotplug_libudev.c:619:HPEstablishUSBNotifications()
00020583 hotplug_libudev.c:642:HPEstablishUSBNotifications() USB Device removed
00000143 hotplug_libudev.c:619:HPEstablishUSBNotifications()
02634822 ifdhandler.c:1143:IFDHPowerICC() action: PowerDown, usb:1050/0115:libudev:1:/dev/bus/usb/003/002 (lun: 0)
00000091 eventhandler.c:479:EHStatusHandlerThread() powerState: POWER_STATE_UNPOWERED

or this:

05000574 ifdhandler.c:1143:IFDHPowerICC() action: PowerDown, usb:1050/0115:libudev:1:/dev/bus/usb/003/002 (lun: 0)
00000261 eventhandler.c:479:EHStatusHandlerThread() powerState: POWER_STATE_UNPOWERED
06904552 hotplug_libudev.c:648:HPEstablishUSBNotifications() USB Device add
00000242 hotplug_libudev.c:294:get_driver() Looking for a driver for VID: 0x046D, PID: 0x0825, path: /dev/bus/usb/003/007
00000015 hotplug_libudev.c:414:HPAddDevice() /dev/bus/usb/003/007 is not a supported smart card reader
00000017 hotplug_libudev.c:619:HPEstablishUSBNotifications()
00022668 hotplug_libudev.c:648:HPEstablishUSBNotifications() USB Device add
00000214 hotplug_libudev.c:294:get_driver() Looking for a driver for VID: 0x046D, PID: 0x0825, path: /dev/bus/usb/003/007
00000013 hotplug_libudev.c:414:HPAddDevice() /dev/bus/usb/003/007 is not a supported smart card reader
00000017 hotplug_libudev.c:619:HPEstablishUSBNotifications()
00006048 hotplug_libudev.c:648:HPEstablishUSBNotifications() USB Device add
00000207 hotplug_libudev.c:294:get_driver() Looking for a driver for VID: 0x046D, PID: 0x0825, path: /dev/bus/usb/003/007
00000014 hotplug_libudev.c:414:HPAddDevice() /dev/bus/usb/003/007 is not a supported smart card reader
00000015 hotplug_libudev.c:619:HPEstablishUSBNotifications()
00014614 hotplug_libudev.c:648:HPEstablishUSBNotifications() USB Device add
00000200 hotplug_libudev.c:294:get_driver() Looking for a driver for VID: 0x046D, PID: 0x0825, path: /dev/bus/usb/003/007
00000016 hotplug_libudev.c:414:HPAddDevice() /dev/bus/usb/003/007 is not a supported smart card reader
00000014 hotplug_libudev.c:619:HPEstablishUSBNotifications()

Basically, if I plug or unplug a USB device, pcscd immediately starting using 100% CPU.

Let me know if there is anything else I can send you to help you debug.

Oh, here's /var/log/syslog from unplugging and replugging in my camera. I Ctrl-C killed pcscd after it went to 100% each time.

pcscd segfaulted.

Mar 4 12:04:11 mawhrin-skel pcscd: debuglog.c:289:DebugLogSetLevel() debug level=debug
Mar 4 12:04:13 mawhrin-skel kernel: [14604.513268] usb 3-1: USB disconnect, device number 6
Mar 4 12:04:13 mawhrin-skel systemd[1]: Reloading Laptop Mode Tools.
Mar 4 12:04:13 mawhrin-skel systemd[1]: Reloaded Laptop Mode Tools.
Mar 4 12:04:13 mawhrin-skel laptop-mode: Laptop mode
Mar 4 12:04:13 mawhrin-skel laptop_mode[17937]: Laptop mode
Mar 4 12:04:13 mawhrin-skel laptop-mode: enabled, not active [unchanged]
Mar 4 12:04:13 mawhrin-skel laptop_mode[17937]: enabled, not active [unchanged]
Mar 4 12:04:53 mawhrin-skel systemd[1]: Starting Laptop Mode Tools - Battery Polling Service...
Mar 4 12:04:53 mawhrin-skel systemd[1]: Reloading Laptop Mode Tools.
Mar 4 12:04:53 mawhrin-skel systemd[1]: Started Laptop Mode Tools - Battery Polling Service.
Mar 4 12:04:53 mawhrin-skel laptop-mode: Laptop mode
Mar 4 12:04:53 mawhrin-skel laptop_mode[17997]: Laptop mode
Mar 4 12:04:53 mawhrin-skel laptop-mode: enabled, not active [unchanged]
Mar 4 12:04:53 mawhrin-skel laptop_mode[17997]: enabled, not active [unchanged]
Mar 4 12:04:53 mawhrin-skel systemd[1]: Reloaded Laptop Mode Tools.
Mar 4 12:05:01 mawhrin-skel CRON[18049]: (root) CMD ([ -x /usr/sbin/dma ] && /usr/sbin/dma -q1)
Mar 4 12:05:17 mawhrin-skel kernel: [14668.018203] pcscd[17921]: segfault at 7f447696064c ip 00007f447696064c sp 00007f447694fed0 error 14 in libc-2.21.so[7f4476d85000+1c0000]
Mar 4 12:05:20 mawhrin-skel pcscd: debuglog.c:289:DebugLogSetLevel() debug level=debug
Mar 4 12:05:30 mawhrin-skel kernel: [14681.443071] usb 3-1: new high-speed USB device number 7 using xhci_hcd
Mar 4 12:05:31 mawhrin-skel kernel: [14681.844167] usb 3-1: New USB device found, idVendor=046d, idProduct=0825
Mar 4 12:05:31 mawhrin-skel kernel: [14681.844175] usb 3-1: New USB device strings: Mfr=0, Product=0, SerialNumber=2
Mar 4 12:05:31 mawhrin-skel kernel: [14681.844179] usb 3-1: SerialNumber: DD923C60
Mar 4 12:05:31 mawhrin-skel kernel: [14681.845342] uvcvideo: Found UVC 1.00 device <unnamed> (046d:0825)
Mar 4 12:05:31 mawhrin-skel kernel: [14681.937806] input: UVC Camera (046d:0825) as /devices/pci0000:00/0000:00:14.0/usb3/3-1/3-1:1.0/input/input19
Mar 4 12:05:32 mawhrin-skel kernel: [14683.279489] usb 3-1: set resolution quirk: cval->res = 384
Mar 4 12:05:32 mawhrin-skel mtp-probe: checking bus 3, device 7: "/sys/devices/pci0000:00/0000:00:14.0/usb3/3-1"
Mar 4 12:05:32 mawhrin-skel mtp-probe: bus: 3, device: 7 was not an MTP device
Mar 4 12:05:32 mawhrin-skel systemd[1]: Reloading Laptop Mode Tools.
Mar 4 12:05:32 mawhrin-skel systemd[1]: Reloaded Laptop Mode Tools.
Mar 4 12:05:32 mawhrin-skel systemd[1]: message repeated 3 times: [ Reloaded Laptop Mode Tools.]
Mar 4 12:05:32 mawhrin-skel systemd-udevd[18064]: Process '/usr/sbin/alsactl -E HOME=/run/alsa restore 1' failed with exit code 99.
Mar 4 12:05:32 mawhrin-skel laptop-mode: Laptop mode
Mar 4 12:05:32 mawhrin-skel laptop_mode[18067]: Laptop mode
Mar 4 12:05:32 mawhrin-skel laptop-mode: ...

Ran it with gdb, reproduced, and then interrupted when it started consuming 100% CPU:

Thread 1 "pcscd" received signal SIGINT, Interrupt.
0x00007ffff74e2853 in select () from /lib/x86_64-linux-gnu/libc.so.6
(gdb) bt
#0 0x00007ffff74e2853 in select () from /lib/x86_64-linux-gnu/libc.so.6
#1 0x0000000000411cfd in ProcessEventsServer (pdwClientID=pdwClientID@entry=0x7fffffffe49c) at winscard_msg_srv.c:223
#2 0x00000000004037f9 in SVCServiceRunLoop () at pcscdaemon.c:128
#3 main (argc=<optimized out>, argv=<optimized out>) at pcscdaemon.c:685
(gdb) info threads
  Id Target Id Frame
* 1 Thread 0x7ffff7fb9740 (LWP 18298) "pcscd" 0x00007ffff74e2853 in select () from /lib/x86_64-linux-gnu/libc.so.6
  2 Thread 0x7ffff6fb0700 (LWP 18302) "pcscd" 0x00007ffff74e09ed in poll () from /lib/x86_64-linux-gnu/libc.so.6
  3 Thread 0x7ffff67af700 (LWP 18303) "pcscd" 0x00007ffff74e09ed in poll () from /lib/x86_64-linux-gnu/libc.so.6
  4 Thread 0x7ffff5fae700 (LWP 18304) "pcscd" 0x00007ffff74e09ed in poll () from /lib/x86_64-linux-gnu/libc.so.6
  5 Thread 0x7ffff57ad700 (LWP 18305) "pcscd" 0x00007ffff74e09ed in poll () from /lib/x86_64-linux-gnu/libc.so.6
(gdb) thread 2
[Switching to thread 2 (Thread 0x7ffff6fb0700 (LWP 18302))]
#0 0x00007ffff74e09ed in poll () from /lib/x86_64-linux-gnu/libc.so.6
(gdb) bt
#0 0x00007ffff74e09ed in poll () from /lib/x86_64-linux-gnu/libc.so.6
#1 0x00007ffff6fc064c in ?? () from /lib/x86_64-linux-gnu/libusb-1.0.so.0
#2 0x00007ffff77b666a in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
#3 0x00007ffff74ec01d in clone () from /lib/x86_64-linux-gnu/libc.so.6
(gdb) thread 3
[Switching to thread 3 (Thread 0x7ffff67af700 (LWP 18303))]
#0 0x00007ffff74e09ed in poll () from /lib/x86_64-linux-gnu/libc.so.6
(gdb) bt
#0 0x00007ffff74e09ed in poll () from /lib/x86_64-linux-gnu/libc.so.6
#1 0x00007ffff6fc064c in ?? () from /lib/x86_64-linux-gnu/libusb-1.0.so.0
#2 0x00007ffff77b666a in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
#3 0x00007ffff74ec01d in clone () from /lib/x86_64-linux-gnu/libc.so.6
(gdb) thread 4
[Switching to thread 4 (Thread 0x7ffff5fae700 (LWP 18304))]
#0 0x00007ffff74e09ed in poll () from /lib/x86_64-linux-gnu/libc.so.6
(gdb) bt
#0 0x00007ffff74e09ed in poll () from /lib/x86_64-linux-gnu/libc.so.6
#1 0x00007ffff6fb9bc5 in ?? () from /lib/x86_64-linux-gnu/libusb-1.0.so.0
#2 0x00007ffff6fbab53 in libusb_handle_events_timeout_completed () from /lib/x86_64-linux-gnu/libusb-1.0.so.0
#3 0x00007ffff6fbac3f in libusb_handle_events () from /lib/x86_64-linux-gnu/libusb-1.0.so.0
#4 0x00007ffff71d64bc in ?? () from /usr/lib/pcsc/drivers/ifd-ccid.bundle/Contents/Linux/libccid.so
#5 0x00007ffff71d0b83 in ?? () from /usr/lib/pcsc/drivers/ifd-ccid.bundle/Contents/Linux/libccid.so
#6 0x00000000004064db in EHStatusHandlerThread (rContext=0x61f010) at eventhandler.c:464
#7 0x00007ffff77b666a in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
#8 0x00007ffff74ec01d in clone () from /lib/x86_64-linux-gnu/libc.so.6
(gdb) thread 5
[Switching to thread 5 (Thread 0x7ffff57ad700 (LWP 18305))]
#0 0x00007ffff74e09ed in poll () from /lib/x86_64-linux-gnu/libc.so.6
(...

Here's a core dump with the corresponding pcscd binary I built from source, which was taken in the above-mentioned gdb session.

Recompiling with --disable-libudev gets rid of the 100% CPU problem and I can still use my smartcard.

If you use --disable-libudev you use use the older hotplug mechanism.
See http://ludovicrousseau.blogspot.com/2011/02/pcscd-now-uses-libudev-instead-of.html

At least that will avoid the 100% CPU issue.

I can work around this with my custom build of pcscd with udev disabled, but it seems that this issue will still affect Debian and Ubuntu users who install the package.

Can we mark this bug as Confirmed, since my symptoms are so similar to the descriptions in the Debian bug[1] you've linked above?

Anything else I can do to help?

Thanks,
Casey

[1] https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=812087

I installed Ubuntu Xenial (beta) in a VirtualBox virtual machine and I can't reproduce the problem :-(

I could connect a CCID reader and a USB mass storage with no problem on pcscd.
Can you reproduce the problem in a Virtual Machine on your side?

Status changed to 'Confirmed' because the bug affects multiple users.

Probably most people using Estonian ID-Card on those distros will be affected? Not good :(

Hmm, conveniently just had a crash. No idea if there is anything useful there :
https://bugs.launchpad.net/ubuntu/+source/pcsc-lite/+bug/1561702

Can you do:
sudo LIBUSB_DEBUG=99 pcscd -dfaT | tee log.txt
and add to this bug the created log.txt file?

hey, sorry, total noob here, what i got is:

00000000 pcscdaemon.c:263:main() pcscd set to foreground with debug send to stdout
00000021 debuglog.c:312:DebugLogSetCategory() Debug options: APDU
00000016 pcscdaemon.c:268:main() Force colored logs
00000037 pcscdaemon.c:403:main() file /var/run/pcscd/pcscd.comm already exists.
00000006 pcscdaemon.c:405:main() Another pcscd (pid: 7349) seems to be running.

Casey, it looks like the problem is related to the use of a "Yubico Yubikey NEO U2F+CCID" device.
Unfortunately I do not have such a device myself so I can't reproduce the problem here :-(

Johnny, why do you say "Probably most people using Estonian ID-Card on those distros will be affected?"?
What smart card reader(s) are provided with the Estonian ID-Card?

Sorry again, Ludovic, i have no idea what this pcscd does so i thought its some general error.
Is this bug device specific? Then i have an Dell laptop with integrated smart-card reader (which im not using physically, since some metal is bended on the way of the card.)
(The most used here is omnikey 1021, but that thing is not connected to the computer when the one cpu-core goes 100%)

Johnny, can you attach the result of the command "lsusb -v"?
Thanks

So in my case it triggers when i connect some usb device (mouse, usb-flash-memory, phone). Sometimes it calms down after unmount and unplug of usb-memory, and does not come back until i logout of lubuntu desktop (and login and plugin again).
Another way of triggering 100% is in my case having usb-memory plugged in and starting firefox. This firefox has estonian id-card plugin installed. I guess that plugin starts looking for id-card or device.

It looks like the problem is related to some specific readers only: Broadcom Corp 5880 and Yubico Yubikey NEO U2F+CCID

Is there a way to disable the device in software, so i could just use my usb card-reader?

Johnny, you can remove the pcscd package if you do not use it.

I use my non-integrated omnikey 1021 usb smartcard-reader, so pcscd is still needed, correct?

I reported the bug upstream to libudev project
https://github.com/systemd/systemd/issues/2946

Johnny, you can disable support of the Broadcom device.

- Get the source code of the libccid driver from https://alioth.debian.org/frs/?group_id=30105#title_ccid.
- edit the file readers/supported_readers.txt
- remove the line "0x0A5C:0x5800:Broadcom Corp 5880"
- run the commands
$ ./configure
$ make
$ make install DESTDIR=/tmp/ccid
$ sudo cp /tmp/ccid/usr/lib/pcsc/drivers/ifd-ccid.bundle/Contents/Info.plist /etc/libccid_Info.plist

Thank you Ludovic.
Laptop is quiet again.
(needed to install -dev files to get over /configure errors, if anyone else is confused)

This is actually a bug in ccid's handling of composite USB devices, and has been fixed upstream (https://alioth.debian.org/plugins/scmgit/cgi-bin/gitweb.cgi?p=pcsclite/CCID.git;a=commitdiff_plain;h=3c21f452543983f3625a1965ce234074cbda6865).

My experience was that this bug caused pcscd to segfault, rather than to consume 100% CPU, but the fix appears to be the same either way.

I've attached a debdiff that fixes the issue for me, and I've uploaded a test build to my PPA (https://launchpad.net/~broder/+archive/ubuntu/ubuntu-tests). I suspect this merits an SRU, since it's a significant regression in functionality without a good workaround; I'll start on the paperwork.

Hello,

I've the same problem with my laptop (Dell Latitude E7450).
If I can help don't hesitate to ask me. I can give you some logs if you want.

Best regards,
Sylvain

Evan: d/patches/close-libusb-on-failure.patch looks fair enough, but what is debian/patches/test? It's a patch of a patch, not referenced/explained in the changelog, what does that do? Please either explain in the changelog or if it is just noise please remove and reupload. Thanks!

Sorry about that, Martin. Not sure what happened. Just re-uploaded without the noise.

Hello Casey, or anyone else affected,

Accepted ccid into xenial-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/ccid/1.4.22-1ubuntu0.1 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation how to enable and use -proposed. Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested, and change the tag from verification-needed to verification-done. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed. In either case, details of your testing will help us make a better decision.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance!

Thanks Martin. I've confirmed that the package solves the issue for me.

This bug was fixed in the package ccid - 1.4.22-1ubuntu0.1

---------------
ccid (1.4.22-1ubuntu0.1) xenial-proposed; urgency=low

  * debian/patches/close-libusb-on-failure.patch: Make sure
    close_libusb_if_needed is called even if no device was opened,
    otherwise it triggers a segfault. (LP: #1551897)

 -- Evan Broder <email address hidden> Mon, 09 May 2016 12:28:36 -0700

The verification of the Stable Release Update for ccid has completed successfully and the package has now been released to -updates. Subsequently, the Ubuntu Stable Release Updates Team is being unsubscribed and will not receive messages about this bug report. In the event that you encounter a regression using the package from -updates please report a new bug using ubuntu-bug and tag the bug report regression-update so we can easily find any regressions.