Bug 657658

Created attachment 478644 [details]
PCSCD CPU Usage

Same issue in Fedora 14.

Occurs when adding the SmartCard Reader into Guest OS (windows running active client) via VMWare Workstation.

Linux localhost.localdomain 2.6.35.11-83.fc14.x86_64 #1 SMP Mon Feb 7 07:06:44 UTC 2011 x86_64 x86_64 x86_64 GNU/Linux


Feb 14 05:53:34 XXX kernel: [ 6376.114982] usb 2-1.6: usbfs: process 19982 (pcscd) did not claim interface 0 before use
Feb 14 05:53:34 x201 pcscd: ifdwrapper.c:481:IFDStatusICC() Card not transacted: 612
Feb 14 05:53:34 XXX kernel: [ 6376.114990] usb 2-1.6: usbfs: process 19982 (pcscd) did not claim interface 0 before use
Feb 14 05:53:34 XXX kernel: [ 6376.115075] usb 2-1.6: usbfs: process 19982 (pcscd) did not claim interface 0 before use
Feb 14 05:53:34 XXX kernel: [ 6376.115082] usb 2-1.6: usbfs: process 19982 (pcscd) did not claim interface 0 before use
Feb 14 05:53:34 XXX pcscd: eventhandler.c:395:EHStatusHandlerThread() Error communicating to: SCM SCR 3340 ExpressCard54 [CCID Interface] (21220929703301) 00 00
Feb 14 05:53:34 XXX pcscd: ccid_usb.c:613:WriteUSB() write failed (2/4): -1 Device or resource busy
Feb 14 05:53:34 XXX pcscd: ifdwrapper.c:481:IFDStatusICC() Card not transacted: 612

same thing on on Ubuntu [1] and Gentoo (my laptop).

 [1]: https://bugs.launchpad.net/ubuntu/+source/pcsc-lite/+bug/776082

(In reply to comment #0)
> Description of problem:
> 
> Nov 26 19:35:24 localhost pcscd: winscard.c:344:SCardConnect() Card Not Powered
[...]
> 
> sometimes various other related errors.  It just keeps going and the file gets
> HUGE, up to 100gb.

I believe the 'Card Not Powered' messages are related to the automatic card power down feature in pcsc-lite. I patched the automatic card power down feature out in F15 because it was unreliable in there too:
http://pkgs.fedoraproject.org/gitweb/?p=pcsc-lite.git;a=blob_plain;f=pcsc-lite-1.6.6-no_auto_power_down;hb=cafc7d6df2481733c2ac1dda640a4bf65c91f265

Not sure if it's worth applying that patch to F14 at this point though. Thoughts?

(In reply to comment #2)
> Occurs when adding the SmartCard Reader into Guest OS (windows running active
> client) via VMWare Workstation.
> 
[...]
> Feb 14 05:53:34 XXX pcscd: eventhandler.c:395:EHStatusHandlerThread() Error
> communicating to: SCM SCR 3340 ExpressCard54 [CCID Interface] (21220929703301)
> 00 00
> Feb 14 05:53:34 XXX pcscd: ccid_usb.c:613:WriteUSB() write failed (2/4): -1
> Device or resource busy
> Feb 14 05:53:34 XXX pcscd: ifdwrapper.c:481:IFDStatusICC() Card not transacted:
> 612

This is something different than the original report, I would suspect a bug in libusb1 instead. libusb upstream is having some issues with getting new releases out and the last release is pretty buggy.

See Ludovic Rousseau's blog posts about libusb releases (or lack thereof):
http://ludovicrousseau.blogspot.com/2011/03/new-version-of-libusb.html
http://ludovicrousseau.blogspot.com/2011/05/new-version-of-libusb-part-2.html

(In reply to comment #3)
> same thing on on Ubuntu [1] and Gentoo (my laptop).
> 
>  [1]: https://bugs.launchpad.net/ubuntu/+source/pcsc-lite/+bug/776082

I've managed to get this too sometimes. 
[ 3666.442390] pcscd[1278]: winscard_svc.c:555:ContextThread() STATUS rv=0x8010000B for client 10
[ 3666.539335] pcscd[1278]: winscard_svc.c:555:ContextThread() STATUS rv=0x8010000B for client 11
[ 3666.542628] pcscd[1278]: winscard_svc.c:555:ContextThread() STATUS rv=0x8010000B for client 10
[ 3666.639550] pcscd[1278]: winscard_svc.c:555:ContextThread() STATUS rv=0x8010000B for client 11

... and it goes on and on.

I would imagine that the client apps are doing something wrong with polling, but still, pcsc-lite logging return values at the ERROR log level is annoyingly noisy and could easily fill up log partitions.

Ludovic, would you consider taking a patch similar to this?

--- src/winscard_svc.c	(revision 5764)
+++ src/winscard_svc.c	(working copy)
@@ -285,7 +285,7 @@
 #define WRITE_BODY(v) \
 	WRITE_BODY_WITH_COMMAND(CommandsText[header.command], v)
 #define WRITE_BODY_WITH_COMMAND(command, v) \
-	Log4(SCARD_S_SUCCESS == v.rv ? PCSC_LOG_DEBUG : PCSC_LOG_ERROR, "%s rv=0x%X for client %d", command, v.rv, filedes); \
+	Log4(PCSC_LOG_DEBUG, "%s rv=0x%X for client %d", command, v.rv, filedes); \
 	ret = MessageSend(&v, sizeof(v), filedes);
 
 static void ContextThread(LPVOID newContext)

(In reply to comment #6)
> Ludovic, would you consider taking a patch similar to this?

Patch applied in revision 5765.
Thanks

pcsc-lite-1.7.2-2.fc15 has been submitted as an update for Fedora 15.
https://admin.fedoraproject.org/updates/pcsc-lite-1.7.2-2.fc15

pcsc-lite-1.6.4-4.fc14 has been submitted as an update for Fedora 14.
https://admin.fedoraproject.org/updates/pcsc-lite-1.6.4-4.fc14

Package pcsc-lite-1.7.2-2.fc15:
* should fix your issue,
* was pushed to the Fedora 15 testing repository,
* should be available at your local mirror within two days.
Update it with:
# su -c 'yum update --enablerepo=updates-testing pcsc-lite-1.7.2-2.fc15'
as soon as you are able to.
Please go to the following url:
https://admin.fedoraproject.org/updates/pcsc-lite-1.7.2-2.fc15
then log in and leave karma (feedback).

Working great now.  No flooding of log files. Required full system restart to get Smart Card to be readable again after update.

Left good karma!

Thank you everybody.

pcsc-lite-1.7.2-2.fc15 has been pushed to the Fedora 15 stable repository.  If problems still persist, please make note of it in this bug report.

pcsc-lite-1.6.4-4.fc14 has been pushed to the Fedora 14 stable repository.  If problems still persist, please make note of it in this bug report.

Hi,

I have pcsc updated, but the problem still persist. The flooding start when I present the activkey SIM to Windows 7 virtualbox guest. As workaround I disconnect the activkey and re-insert again. After disconnect flooding stops. So I re-insert activkey and present to virtualbox guest and flooding don't start again.  I notice a core dump from pcsc process in the messages log. Let me know it I have to upload some more information.

[root@cschimidt3 log]# rpm -qa | grep pcsc
pcsc-tools-1.4.17-1.fc14.x86_64
pcsc-lite-1.6.4-4.fc14.x86_64
pcsc-lite-libs-1.6.4-4.fc14.i686
pcsc-lite-debuginfo-1.6.4-4.fc14.x86_64
pcsc-perl-1.4.12-1.fc14.x86_64
pcsc-lite-doc-1.6.4-4.fc14.noarch
pcsc-lite-devel-1.6.4-4.fc14.x86_64
pcsc-lite-libs-1.6.4-4.fc14.x86_64


[root@cschimidt3 log]# tail -f messages 
Jul  4 11:57:30 cschimidt3 kernel: [  140.424178] usb 5-1: new full speed USB device using ohci_hcd and address 3
Jul  4 11:57:30 cschimidt3 kernel: [  140.577724] usb 5-1: New USB device found, idVendor=09c3, idProduct=0014
Jul  4 11:57:30 cschimidt3 kernel: [  140.577735] usb 5-1: New USB device strings: Mfr=1, Product=2, SerialNumber=0
Jul  4 11:57:30 cschimidt3 kernel: [  140.577743] usb 5-1: Product: Activkey_Sim
Jul  4 11:57:30 cschimidt3 kernel: [  140.577749] usb 5-1: Manufacturer: ActivIdentity
Jul  4 11:57:30 cschimidt3 mtp-probe: checking bus 5, device 3: "/sys/devices/pci0000:00/0000:00:13.0/usb5/5-1"
Jul  4 11:57:30 cschimidt3 mtp-probe: bus: 5, device: 3 was not an MTP device

Jul  4 11:58:16 cschimidt3 kernel: [  186.238621] warning: `VirtualBox' uses 32-bit capabilities (legacy support in use)
Jul  4 11:58:26 cschimidt3 pulseaudio[3064]: ratelimit.c: 3 events suppressed
Jul  4 11:58:47 cschimidt3 kernel: [  217.307018] usb 5-1: usbfs: process 3661 (pcscd) did not claim interface 0 before use
Jul  4 11:58:48 cschimidt3 pulseaudio[3064]: ratelimit.c: 4 events suppressed
Jul  4 11:58:49 cschimidt3 pcscd: ccid_usb.c:613:WriteUSB() write failed (5/3): -1 Device or resource busy
Jul  4 11:58:49 cschimidt3 pcscd: ifdwrapper.c:481:IFDStatusICC() Card not transacted: 612
Jul  4 11:58:49 cschimidt3 pcscd: eventhandler.c:395:EHStatusHandlerThread() Error communicating to: Activkey Sim 01 00
Jul  4 11:58:49 cschimidt3 pcscd: ccid_usb.c:613:WriteUSB() write failed (5/3): -1 Device or resource busy
Jul  4 11:58:49 cschimidt3 pcscd: ifdwrapper.c:481:IFDStatusICC() Card not transacted: 612
Jul  4 11:58:49 cschimidt3 pcscd: eventhandler.c:395:EHStatusHandlerThread() Error communicating to: Activkey Sim 01 00
Jul  4 11:58:49 cschimidt3 pcscd: ccid_usb.c:613:WriteUSB() write failed (5/3): -1 Device or resource busy
Jul  4 11:58:49 cschimidt3 pcscd: ifdwrapper.c:481:IFDStatusICC() Card not transacted: 612
Jul  4 11:58:49 cschimidt3 pcscd: eventhandler.c:395:EHStatusHandlerThread() Error communicating to: Activkey Sim 01 00
Jul  4 11:58:49 cschimidt3 pcscd: ccid_usb.c:613:WriteUSB() write failed (5/3): -1 Device or resource busy
Jul  4 11:58:49 cschimidt3 pcscd: ifdwrapper.c:481:IFDStatusICC() Card not transacted: 612
...

Jul  4 12:01:20 cschimidt3 kernel: [  370.347464] usb 5-1: usbfs: process 3661 (pcscd) did not claim interface 0 before use
Jul  4 12:01:20 cschimidt3 kernel: [  370.347499] usb 5-1: usbfs: process 3661 (pcscd) did not claim interface 0 before use
Jul  4 12:01:20 cschimidt3 pcscd: ccid_usb.c:613:WriteUSB() write failed (5/3): -1 Device or resource busy
Jul  4 12:01:20 cschimidt3 kernel: [  370.347503] usb 5-1: usbfs: process 3661 (pcscd) did not claim interface 0 before use
Jul  4 12:01:20 cschimidt3 kernel: [  370.347519] usb 5-1: usbfs: process 3661 (pcscd) did not claim interface 0 before use
Jul  4 12:01:20 cschimidt3 kernel: [  370.347523] usb 5-1: usbfs: process 3661 (pcscd) did not claim interface 0 before use
Jul  4 12:01:20 cschimidt3 kernel: [  370.347538] usb 5-1: usbfs: process 3661 (pcscd) did not claim interface 0 before use
Jul  4 12:01:20 cschimidt3 kernel: [  370.347542] usb 5-1: usbfs: process 3661 (pcscd) did not claim interface 0 before use
Jul  4 12:01:20 cschimidt3 kernel: [  370.347557] usb 5-1: usbfs: process 3661 (pcscd) did not claim interface 0 before use
Jul  4 12:01:20 cschimidt3 kernel: [  370.347561] usb 5-1: usbfs: process 3661 (pcscd) did not claim interface 0 before use


Jul  4 12:01:56 cschimidt3 pcscd: *** glibc detected *** pcscd: double free or corruption (fasttop): 0x00007f5d44000a00 ***
Jul  4 12:01:56 cschimidt3 abrt[3943]: saved core dump of pid 1984 (/usr/sbin/pcscd) to /var/spool/abrt/ccpp-1309791716-1984.new/coredump (26206208 bytes)

The "usbfs: process 3661 (pcscd) did not claim interface 0 before use" is actually a different problem, see bug #718375 and https://bugs.launchpad.net/ubuntu/+source/pcsc-lite/+bug/787451

I believe it is best to just stop pcscd before attaching the device in Virtualbox.

Please post further comments about this in bug #718375. Thank you!

Thanks. I'll follow up the bug #718375. Sorry my mistake.

Carlos, your problem is not the same as the problem initialy discussed in this bug. Kalev gave the solution.