Bug 718375

Summary:	PCSCD filling /var/log/messages
Product:	[Fedora] Fedora	Reporter:	Vincent passaro <vincent.passaro>
Component:	pcsc-lite	Assignee:	Kalev Lember <kalevlember>
Status:	CLOSED ERRATA	QA Contact:	Fedora Extras Quality Assurance <extras-qa>
Severity:	high	Docs Contact:
Priority:	unspecified
Version:	15	CC:	crschimidt, kalevlember, rrelyea
Target Milestone:	---
Target Release:	---
Hardware:	x86_64
OS:	Linux
Whiteboard:
Fixed In Version:	pcsc-lite-1.7.2-3.fc15	Doc Type:	Bug Fix
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2011-07-12 05:21:22 UTC	Type:	---
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:

Description Vincent passaro 2011-07-02 05:00:16 UTC

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:

Comment 1 Vincent passaro 2011-07-02 05:03:21 UTC

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

Comment 2 Kalev Lember 2011-07-02 13:48:58 UTC

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

Comment 3 Fedora Update System 2011-07-02 14:19:35 UTC

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

Comment 4 Kalev Lember 2011-07-02 14:20:51 UTC

Can you test if the update above slows down the message rate?

Comment 5 Vincent passaro 2011-07-02 19:22:24 UTC

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.

Comment 6 Fedora Update System 2011-07-02 19:23:29 UTC

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).

Comment 7 Vincent passaro 2011-07-02 20:18:42 UTC

Just tried the update and it wasn't available. 

Will try back later.

Comment 8 Carlos Schimidt 2011-07-04 19:23:56 UTC

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)

Comment 9 Vincent passaro 2011-07-04 19:45:28 UTC

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

Comment 10 Kalev Lember 2011-07-08 20:31:19 UTC

(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.

Comment 11 Fedora Update System 2011-07-12 05:21:16 UTC

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.