Bug 657658 - Pcscd flooding /var/log/messages, creating file > gb
Summary: Pcscd flooding /var/log/messages, creating file > gb
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: pcsc-lite
Version: 14
Hardware: x86_64
OS: Unspecified
low
medium
Target Milestone: ---
Assignee: Bob Relyea
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2010-11-27 01:42 UTC by roygbiver
Modified: 2011-07-05 07:59 UTC (History)
6 users (show)

Fixed In Version: pcsc-lite-1.6.4-4.fc14
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2011-05-29 23:22:54 UTC
Type: ---


Attachments (Terms of Use)
PCSCD CPU Usage (138.59 KB, image/png)
2011-02-14 15:00 UTC, Vincent passaro
no flags Details

Description roygbiver 2010-11-27 01:42:07 UTC
Description of problem:

Nov 26 19:35:24 localhost pcscd: winscard.c:344:SCardConnect() Card Not Powered
Nov 26 19:35:24 localhost pcscd: winscard_svc.c:447:ContextThread() CONNECT rv=0x80100067 for client 4
Nov 26 19:38:14 localhost pcscd: winscard.c:338:SCardConnect() Card Not Inserted
Nov 26 19:38:14 localhost pcscd: winscard_svc.c:447:ContextThread() CONNECT rv=0x8010000C for client 4

sometimes various other related errors.  It just keeps going and the file gets HUGE, up to 100gb.

Comment 1 Vincent passaro 2011-02-14 15:00:53 UTC
Created attachment 478644 [details]
PCSCD CPU Usage

Comment 2 Vincent passaro 2011-02-14 15:04:20 UTC
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

Comment 3 Leho Kraav 2011-05-18 10:44:14 UTC
same thing on on Ubuntu [1] and Gentoo (my laptop).

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

Comment 4 Kalev Lember 2011-05-20 15:19:39 UTC
(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?

Comment 5 Kalev Lember 2011-05-20 15:24:46 UTC
(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

Comment 6 Kalev Lember 2011-05-20 15:34:32 UTC
(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)

Comment 7 Ludovic Rousseau 2011-05-22 11:34:21 UTC
(In reply to comment #6)
> Ludovic, would you consider taking a patch similar to this?

Patch applied in revision 5765.
Thanks

Comment 8 Fedora Update System 2011-05-25 08:12:55 UTC
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

Comment 9 Fedora Update System 2011-05-25 08:13:12 UTC
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

Comment 10 Fedora Update System 2011-05-25 18:52:37 UTC
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).

Comment 11 Vincent passaro 2011-05-26 00:16:46 UTC
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.

Comment 12 Fedora Update System 2011-05-29 23:22:43 UTC
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.

Comment 13 Fedora Update System 2011-06-03 05:30:57 UTC
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.

Comment 14 Carlos Schimidt 2011-07-04 17:35:10 UTC
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)

Comment 15 Kalev Lember 2011-07-04 18:13:41 UTC
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!

Comment 16 Carlos Schimidt 2011-07-04 19:21:40 UTC
Thanks. I'll follow up the bug #718375. Sorry my mistake.

Comment 17 Ludovic Rousseau 2011-07-05 07:59:05 UTC
Carlos, your problem is not the same as the problem initialy discussed in this bug. Kalev gave the solution.


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