Description of problem: PCSCD is logging excessively to /var/log/messages with the following information: Jul 1 21:58:32 x201 kernel: [ 526.206339] usb 2-1.6: usbfs: process 1230 (pcscd) did not claim interface 0 before use Jul 1 21:58:32 x201 kernel: [ 526.206344] usb 2-1.6: usbfs: process 1230 (pcscd) did not claim interface 0 before use Jul 1 21:58:32 x201 kernel: [ 526.206386] usb 2-1.6: usbfs: process 1230 (pcscd) did not claim interface 0 before use Jul 1 21:58:32 x201 kernel: [ 526.206393] usb 2-1.6: usbfs: process 1230 (pcscd) did not claim interface 0 before use Jul 1 21:58:32 x201 kernel: [ 526.206421] usb 2-1.6: usbfs: process 1230 (pcscd) did not claim interface 0 before use Jul 1 21:58:32 x201 kernel: [ 526.206428] usb 2-1.6: usbfs: process 1230 (pcscd) did not claim interface 0 before use Jul 1 21:58:32 x201 kernel: [ 526.206450] usb 2-1.6: usbfs: process 1230 (pcscd) did not claim interface 0 before use Jul 1 21:58:32 x201 kernel: [ 526.206455] usb 2-1.6: usbfs: process 1230 (pcscd) did not claim interface 0 before use Jul 1 21:58:32 x201 kernel: [ 526.206476] usb 2-1.6: usbfs: process 1230 (pcscd) did not claim interface 0 before use Jul 1 21:58:32 x201 kernel: [ 526.206482] usb 2-1.6: usbfs: process 1230 (pcscd) did not claim interface 0 before use Version-Release number of selected component (if applicable): pcsc-lite-1.7.2-2.fc15.x86_64 How reproducible: Always Steps to Reproduce: 1. Turn on pcscd service 2. Logging occurs 3. /var/log/messages fills to partition / drive capacity Actual results: Logging is too verbose. Expected results: Logging would not be as verbose. Additional info:
Just to put it into perspective on how much is being logged. In the time it took me to write the bugzilla report it filled my /var/log partition (1GB) (so about 4 minutes) /dev/sda3 985M 985M 0 100% /var/log
Are you using VMWare Workstation? Ludovic Rousseau has looked into what appears to be the same bug: https://bugs.launchpad.net/ubuntu/+source/pcsc-lite/+bug/787451 His conclusion was that it's actually a bug in VMWare Workstation, but he came up with a fix to pcscd to avoid retrying too fast in case of error. This should limit the amount of the "did not claim interface 0 before use" messages the linux kernel is spitting out. I could backport this patch to F15 to slow down the message rate, but this won't fix the actual problem: http://lists.alioth.debian.org/pipermail/pcsclite-cvs-commit/2011-May/005320.html
pcsc-lite-1.7.2-3.fc15 has been submitted as an update for Fedora 15. https://admin.fedoraproject.org/updates/pcsc-lite-1.7.2-3.fc15
Can you test if the update above slows down the message rate?
I do have vmware workstation installed on the machine, but wasn't running at the time this occurred. The card reader was being used with a libvirt windows image. I will test the updated and report back.
Package pcsc-lite-1.7.2-3.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-3.fc15' as soon as you are able to. Please go to the following url: https://admin.fedoraproject.org/updates/pcsc-lite-1.7.2-3.fc15 then log in and leave karma (feedback).
Just tried the update and it wasn't available. Will try back later.
Hi, Is there an update for FC14 about this issue? 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.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)
Ran suggested update, rebooted the system, and then started a Windows Libvirt VM with the PCI express card bound to it. su -c 'yum update --enablerepo=updates-testing pcsc-lite-1.7.2-3.fc15' Excessive logging is still occurring, but not on the level it was before, so it's an improvement but not a fix. --MESSAGES BELOW-- Jul 4 12:43:37 x201 pcscd: ccid_usb.c:601:WriteUSB() write failed (2/4): -1 Device or resource busy Jul 4 12:43:37 x201 pcscd: ifdwrapper.c:346:IFDStatusICC() Card not transacted: 612 Jul 4 12:43:37 x201 pcscd: eventhandler.c:303:EHStatusHandlerThread() Error communicating to: SCM SCR 3340 ExpressCard54 [CCID Interface] (21220929703301) 00 00 Jul 4 12:43:38 x201 pcscd: ccid_usb.c:601:WriteUSB() write failed (2/4): -1 Device or resource busy Jul 4 12:43:38 x201 pcscd: ifdwrapper.c:346:IFDStatusICC() Card not transacted: 612 Jul 4 12:43:38 x201 pcscd: eventhandler.c:303:EHStatusHandlerThread() Error communicating to: SCM SCR 3340 ExpressCard54 [CCID Interface] (21220929703301) 00 00 Jul 4 12:43:38 x201 kernel: [ 312.973010] usb 2-1.6: usbfs: process 1232 (pcscd) did not claim interface 0 before use Jul 4 12:43:38 x201 kernel: [ 312.973123] usb 2-1.6: usbfs: process 1232 (pcscd) did not claim interface 0 before use Jul 4 12:43:38 x201 pcscd: ccid_usb.c:601:WriteUSB() write failed (2/4): -1 Device or resource busy Jul 4 12:43:38 x201 pcscd: ifdwrapper.c:346:IFDStatusICC() Card not transacted: 612 Jul 4 12:43:38 x201 pcscd: eventhandler.c:303:EHStatusHandlerThread() Error communicating to: SCM SCR 3340 ExpressCard54 [CCID Interface] (21220929703301) 00 00 Jul 4 12:43:38 x201 kernel: [ 313.372147] usb 2-1.6: usbfs: process 1232 (pcscd) did not claim interface 0 before use Jul 4 12:43:38 x201 kernel: [ 313.372263] usb 2-1.6: usbfs: process 1232 (pcscd) did not claim interface 0 before use Jul 4 12:43:39 x201 pcscd: ccid_usb.c:601:WriteUSB() write failed (2/4): -1 Device or resource busy Jul 4 12:43:39 x201 pcscd: ifdwrapper.c:346:IFDStatusICC() Card not transacted: 612 Jul 4 12:43:39 x201 pcscd: eventhandler.c:303:EHStatusHandlerThread() Error communicating to: SCM SCR 3340 ExpressCard54 [CCID Interface] (21220929703301) 00 00 Jul 4 12:43:39 x201 kernel: [ 313.771279] usb 2-1.6: usbfs: process 1232 (pcscd) did not claim interface 0 before use Jul 4 12:43:39 x201 kernel: [ 313.771381] usb 2-1.6: usbfs: process 1232 (pcscd) did not claim interface 0 before use Jul 4 12:43:39 x201 pcscd: ccid_usb.c:601:WriteUSB() write failed (2/4): -1 Device or resource busy Jul 4 12:43:39 x201 pcscd: ifdwrapper.c:346:IFDStatusICC() Card not transacted: 612 Jul 4 12:43:39 x201 pcscd: eventhandler.c:303:EHStatusHandlerThread() Error communicating to: SCM SCR 3340 ExpressCard54 [CCID Interface] (21220929703301) 00 00 Jul 4 12:43:39 x201 kernel: [ 314.170385] usb 2-1.6: usbfs: process 1232 (pcscd) did not claim interface 0 before use Jul 4 12:43:39 x201 kernel: [ 314.170484] usb 2-1.6: usbfs: process 1232 (pcscd) did not claim interface 0 before use Jul 4 12:43:39 x201 kernel: [ 314.569454] usb 2-1.6: usbfs: process 1232 (pcscd) did not claim interface 0 before use
(In reply to comment #8) > Is there an update for FC14 about this issue? > > 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. Carlos, just stop pcscd before attaching the device to virtualbox. The F15 update only just makes the flooding *slower*, but doesn't fix the underlying cause. I don't think it's worth doing a F14 update for that.
pcsc-lite-1.7.2-3.fc15 has been pushed to the Fedora 15 stable repository. If problems still persist, please make note of it in this bug report.