I'm encountering an intermittent segv, plus weird diagnostics in /var/log/messages for a f19 pcscd running against a USB Yubikey NEO that's plugged in and out a couple of times an hour. (Note this machine also has a TPM and related daemons running.) See also bug #674612. Here is a sampling of /var/log/messages: Mar 20 10:45:35 very pcscd[15616]: 00000002 winscard.c:1606:SCardTransmit() Card not transacted: 0x80100016 Mar 20 10:45:35 very pcscd[15616]: 00008981 commands.c:1401:CCID_Receive Slot busy Mar 20 10:45:35 very pcscd[15616]: 00000006 ifdwrapper.c:527:IFDTransmit() Card not transacted: 612 Mar 20 10:45:35 very pcscd[15616]: 00000002 winscard.c:1606:SCardTransmit() Card not transacted: 0x80100016 Mar 20 10:45:35 very pcscd[15616]: 00004576 commands.c:1401:CCID_Receive Slot busy Mar 20 10:45:35 very pcscd[15616]: 00000004 ifdwrapper.c:527:IFDTransmit() Card not transacted: 612 Mar 20 10:45:35 very pcscd[15616]: 00000002 winscard.c:1606:SCardTransmit() Card not transacted: 0x80100016 Mar 20 10:45:35 very pcscd[15616]: 00006998 winscard.c:926:SCardDisconnect() Error resetting card. Mar 20 10:45:47 very pcscd[15616]: 12177035 readerfactory.c:1104:RFAddReaderHandle() Too many handles opened, exceeding configured max (200) Mar 20 10:45:47 very pcscd[15616]: 00000083 readerfactory.c:1104:RFAddReaderHandle() Too many handles opened, exceeding configured max (200) Mar 20 10:45:48 very pcscd[15616]: 01000647 readerfactory.c:1104:RFAddReaderHandle() Too many handles opened, exceeding configured max (200) [... then many near-identical messages ...] Mar 21 11:57:42 very pcscd[8646]: 00000080 readerfactory.c:1104:RFAddReaderHandle() Too many handles opened, exceeding configured max (200) Mar 21 11:57:42 very pcscd[8646]: 00000080 readerfactory.c:1104:RFAddReaderHandle() Too many handles opened, exceeding configured max (200) Mar 21 11:57:42 very pcscd[8646]: 00000150 readerfactory.c:1104:RFAddReaderHandle() Too many handles opened, exceeding configured max (200) Mar 21 11:57:42 very pcscd[8646]: 00000073 readerfactory.c:1104:RFAddReaderHandle() Too many handles opened, exceeding configured max (200) Mar 21 11:57:43 very pcscd[8646]: 01000587 winscard.c:240:SCardConnect() Reader Yubico Yubikey NEO OTP+CCID 00 00 Not Found Mar 21 11:57:43 very pcscd[8646]: 00000097 winscard.c:240:SCardConnect() Reader Yubico Yubikey NEO OTP+CCID 00 00 Not Found Mar 21 11:57:43 very pcscd[8646]: 00000093 winscard.c:240:SCardConnect() Reader Yubico Yubikey NEO OTP+CCID 00 00 Not Found Mar 21 11:57:43 very pcscd[8646]: 00052144 ccid_usb.c:660:WriteUSB() write failed (3/7): -4 No such device Mar 21 11:57:43 very kernel: [ 834.244478] pcscd[8925]: segfault at 7f7c18e2a5f8 ip 00007f7c18e2a5f8 sp 00007f7c19a4bee0 error 14 Mar 21 11:57:43 very kernel: [ 834.244484] CPU: 1 PID: 8925 Comm: pcscd Tainted: PF O 3.13.6-100.fc19.x86_64 #1 Mar 21 11:57:43 very abrt-hook-ccpp[9471]: Saved core dump of pid 8646 (/usr/sbin/pcscd) to /var/tmp/abrt/ccpp-2014-03-21-11:57:43-8646 (43270144 bytes) Mar 21 11:57:43 very systemd[1]: pcscd.service: main process exited, code=dumped, status=11/SEGV Mar 21 11:57:43 very systemd[1]: Unit pcscd.service entered failed state. Mar 21 13:38:38 very pcscd[10157]: 00000000 winscard.c:240:SCardConnect() Reader E-Gate 0 0 Not Found Mar 21 13:38:38 very pcscd[10157]: 00000362 winscard.c:240:SCardConnect() Reader E-Gate 0 0 Not Found Mar 21 13:38:38 very pcscd[10157]: 00000048 winscard.c:240:SCardConnect() Reader E-Gate 0 0 Not Found The backtrace at the moment of crash appears to implicate memory corruption, possibly related to concurrent free()ing: Core was generated by `/usr/sbin/pcscd --foreground --auto-exit'. Program terminated with signal 11, Segmentation fault. #0 0x00007f7a862b05f8 in ?? () (gdb) bt #0 0x00007f7a862b05f8 in ?? () #1 0x00007f7a894a3850 in __elf_set___libc_thread_subfreeres_element___rpc_thread_destroy__ () #2 0x00007f7a894a3848 in __elf_set___libc_thread_subfreeres_element_res_thread_freeres__ () from /lib64/libc.so.6 #3 0x0000000100000009 in ?? () #4 0x0001000100000008 in ?? () #5 0x0000000000000000 in ?? () (gdb) thread apply all bt Thread 7 (Thread 0x7f7a89ece740 (LWP 8828)): #0 0x00007f7a891da553 in select () at ../sysdeps/unix/syscall-template.S:81 #1 0x0000000000410ba0 in ProcessEventsServer (pdwClientID=pdwClientID@entry=0x7fff302061dc) at winscard_msg_srv.c:202 #2 0x00000000004035b0 in SVCServiceRunLoop () at pcscdaemon.c:89 #3 main (argc=<optimized out>, argv=<optimized out>) at pcscdaemon.c:630 Thread 6 (Thread 0x7f7a886d5700 (LWP 8830)): #0 0x00007f7a891da553 in select () at ../sysdeps/unix/syscall-template.S:81 #1 0x0000000000410865 in MessageReceive (buffer_void=buffer_void@entry=0x7f7a886b4e60, buffer_size=buffer_size@entry=8, filedes=filedes@entry=4) at winscard_msg.c:442 #2 0x0000000000411431 in ContextThread (newContext=0x1ea3d10) at winscard_svc.c:304 #3 0x00007f7a894b5c53 in start_thread (arg=0x7f7a886d5700) at pthread_create.c:308 #4 0x00007f7a891e2dbd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113 Thread 5 (Thread 0x7f7a87ed4700 (LWP 9299)): #0 0x00007f7a891da553 in select () at ../sysdeps/unix/syscall-template.S:81 #1 0x0000000000410865 in MessageReceive (buffer_void=buffer_void@entry=0x7f7a87eb3e60, buffer_size=buffer_size@entry=8, filedes=filedes@entry=6) at winscard_msg.c:442 #2 0x0000000000411431 in ContextThread (newContext=0x1ea3f40) at winscard_svc.c:304 #3 0x00007f7a894b5c53 in start_thread (arg=0x7f7a87ed4700) at pthread_create.c:308 #4 0x00007f7a891e2dbd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113 ---Type <return> to continue, or q <return> to quit--- Thread 4 (Thread 0x7f7a862a1700 (LWP 9674)): #0 0x00007f7a891d87fd in poll () at ../sysdeps/unix/syscall-template.S:81 #1 0x00007f7a862b05f8 in ?? () #2 0x0000000000000000 in ?? () Thread 3 (Thread 0x7f7a876d3700 (LWP 9620)): #0 0x00007f7a891da553 in select () at ../sysdeps/unix/syscall-template.S:81 #1 0x0000000000410865 in MessageReceive (buffer_void=buffer_void@entry=0x7f7a876b2e60, buffer_size=buffer_size@entry=8, filedes=filedes@entry=7) at winscard_msg.c:442 #2 0x0000000000411431 in ContextThread (newContext=0x1ebe4d0) at winscard_svc.c:304 #3 0x00007f7a894b5c53 in start_thread (arg=0x7f7a876d3700) at pthread_create.c:308 #4 0x00007f7a891e2dbd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113 Thread 2 (Thread 0x7f7a88ed6700 (LWP 8829)): #0 __GI___libc_free (mem=0x7f7a800028e0) at malloc.c:2885 #1 0x00007f7a898d5f93 in udev_list_entry_delete (entry=entry@entry=0x7f7a80018550) at ../src/libudev/libudev-list.c:242 #2 0x00007f7a898d605e in udev_list_cleanup (list=list@entry=0x7f7a80002160) at ../src/libudev/libudev-list.c:257 #3 0x00007f7a898d6a2b in udev_device_unref (udev_device=udev_device@entry=0x7f7a800020a0) at ../src/libudev/libudev-device.c:1106 #4 0x00007f7a898d9e01 in scan_dir_and_add_devices ( udev_enumerate=udev_enumerate@entry=0x7f7a800029b0, basedir=basedir@entry=0x7f7a898de271 "bus", subdir1=subdir1@entry=0x7f7a80042423 "usb", subdir2=subdir2@entry=0x7f7a898de269 "devices") at ../src/libudev/libudev-enumerate.c:711 #5 0x00007f7a898d9fde in scan_dir (udev_enumerate=udev_enumerate@entry=0x7f7a800029b0, basedir=basedir@entry=0x7f7a898de271 "bus", subdir=subdir@entry=0x7f7a898de269 "devices", subsystem=subsystem@entry=0x0) at ../src/libudev/libudev-enumerate.c:752 #6 0x00007f7a898da810 in scan_devices_all (udev_enumerate=0x7f7a800029b0) at ../src/libudev/libudev-enumerate.c:899 #7 udev_enumerate_scan_devices (udev_enumerate=udev_enumerate@entry=0x7f7a800029b0) at ../src/libudev/libudev-enumerate.c:928 #8 0x000000000040dfc9 in HPRescanUsbBus (udev=udev@entry=0x1eabe30) at hotplug_libudev.c:426 #9 0x000000000040e451 in HPEstablishUSBNotifications (udev=0x1eabe30) at hotplug_libudev.c:588 #10 0x00007f7a894b5c53 in start_thread (arg=0x7f7a88ed6700) at pthread_create.c:308 #11 0x00007f7a891e2dbd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113 Thread 1 (Thread 0x7f7a86ed2700 (LWP 9673)): #0 0x00007f7a862b05f8 in ?? () #1 0x00007f7a894a3850 in __elf_set___libc_thread_subfreeres_element___rpc_thread_destroy__ () #2 0x00007f7a894a3848 in __elf_set___libc_thread_subfreeres_element_res_thread_freeres__ () from /lib64/libc.so.6 #3 0x0000000100000009 in ?? () #4 0x0001000100000008 in ?? () #5 0x0000000000000000 in ?? ()
I have no idea where the bug comes from. The backtrace do not give much information. What is the output of "/usr/sbin/pcscd --version"?
Yeah, the backtrace is not great. The one the retrace server tried to compute was even worse :-) % pcscd --version pcsc-lite version 1.8.8.
In pcsc-lite 1.8.9 I fixed a bug that may be related: - hotplug_libudev.c: Fix a memory leak in case of error I find it very strange the log message: readerfactory.c:1104:RFAddReaderHandle() Too many handles opened, exceeding configured max (200) Your application is doing something strange. What is your application? What is it doing?
"What is your application? What is it doing?" Nothing I wrote. It could be firefox, with a coolkey pkcs#11 driver and/or via opensc. Can you suggest some configuration options to increase diagnostics?
OK, it seems to be repeatable thusly: 0) start pcscd service 1) plug in yubikey neo 2) run pkcs11-tool --module /usr/lib64/pkcs11/opensc-pkcs11.so -L Available slots: Slot 0 (0xffffffffffffffff): Virtual hotplug slot (empty) Slot 1 (0x1): (GetSlotInfo failed, CKR_GENERAL_ERROR) 3) pull out yubikey neo 4) observe segv & abrt activity 5) observe systemd restarting PC/SC Smart Card Daemon after yubikey is reinserted
Do you also have the crash is you do not run pkcs11-tool? Please follow http://pcsclite.alioth.debian.org/pcsclite.html#support to generate a _full_ pcscd trace
The problem still occurs, without pkcs11-tool being manually run. I will attach the log from the more elaborate trace and the abrt coredump backtrace.
Created attachment 902524 [details] detailed pcscd log to recreate: start pcscd with requested options; insert yubico neo; remove yubico neo
Created attachment 902525 [details] abrt core_backtrace
It looks like the crash occurs inside udev_enumerate_scan_devices() from /lib64/libudev.so.1 Maybe a bug in libudev?
Frank could we have a trace of the crash with valgrind? (just run pcscd under valgrind and attach the output). It could be easier then to determine whether the issue is in pcscd or libudev.
valgrind run on the same trace-flag-laden pcscd invocation opines: [...] 00000280 readerfactory.c:1029:RFUnInitializeReader() Attempting shutdown of Yubico Yubikey NEO OTP+CCID 00 00. 00000870 ifdhandler.c:249:IFDHCloseChannel() usb:1050/0111:libudev:1:/dev/bus/usb/003/051 (lun: 0) 00000560 -> 000000 63 00 00 00 00 00 08 00 00 00 00000110 ccid_usb.c:660:WriteUSB() write failed (3/51): -4 No such device 00000529 ccid_usb.c:742:CloseUSB() Closing USB device: 3/51 00000357 ccid_usb.c:763:CloseUSB() Last slot closed. Release resources 00003944 readerfactory.c:905:RFUnloadReader() Unloading reader driver. ==21283== Thread 3: ==21283== Jump to the invalid address stated on the next line ==21283== at 0x646B5F8: ??? ==21283== Address 0x646b5f8 is not stack'd, malloc'd or (recently) free'd ==21283== ==21283== ==21283== Process terminating with default action of signal 11 (SIGSEGV): dumping core ==21283== Access not within mapped region at address 0x646B5F8 ==21283== at 0x646B5F8: ??? ==21283== If you believe this happened as a result of a stack ==21283== overflow in your program's main thread (unlikely but ==21283== possible), you can try to increase the size of the ==21283== main thread stack using the --main-stacksize= flag. ==21283== The main thread stack size used in this run was 16777216. ==21283== ==21283== HEAP SUMMARY: ==21283== in use at exit: 342,996 bytes in 4,900 blocks ==21283== total heap usage: 15,046 allocs, 10,146 frees, 1,483,663 bytes allocated ==21283== ==21283== LEAK SUMMARY: ==21283== definitely lost: 23,048 bytes in 59 blocks ==21283== indirectly lost: 212,051 bytes in 3,966 blocks ==21283== possibly lost: 29,197 bytes in 80 blocks ==21283== still reachable: 78,700 bytes in 795 blocks ==21283== suppressed: 0 bytes in 0 blocks ==21283== Rerun with --leak-check=full to see details of leaked memory ==21283== ==21283== For counts of detected and suppressed errors, rerun with: -v ==21283== ERROR SUMMARY: 1 errors from 1 contexts (suppressed: 2 from 2) Running under gdb: Program received signal SIGUSR1, User defined signal 1. 0x00002b9c5e18a553 in select () at ../sysdeps/unix/syscall-template.S:81 81 T_PSEUDO (SYSCALL_SYMBOL, SYSCALL_NAME, SYSCALL_NARGS) Missing separate debuginfos, use: debuginfo-install pcsc-lite-ccid-1.4.10-1.fc19.x86_64 (gdb) bt #0 0x00002b9c5e18a553 in select () at ../sysdeps/unix/syscall-template.S:81 #1 0x0000000000410ba0 in ProcessEventsServer (pdwClientID=pdwClientID@entry=0x7ffffaa777dc) at winscard_msg_srv.c:202 #2 0x00000000004035b0 in SVCServiceRunLoop () at pcscdaemon.c:89 #3 main (argc=<optimized out>, argv=<optimized out>) at pcscdaemon.c:630 (gdb) signal SIGUSR1 Continuing with signal SIGUSR1. 12511557 eventhandler.c:446:EHStatusHandlerThread() powerState: POWER_STATE_UNPOWERED 00000007 eventhandler.c:469:EHStatusHandlerThread() Die 00001440 eventhandler.c:188:EHDestroyEventHandler() Thread stomped. 00000007 readerfactory.c:1029:RFUnInitializeReader() Attempting shutdown of Yubico Yubikey NEO OTP+CCID 00 00. 00000006 ifdhandler.c:249:IFDHCloseChannel() usb:1050/0111:libudev:1:/dev/bus/usb/003/052 (lun: 0) 00000003 -> 000000 63 00 00 00 00 00 08 00 00 00 [Thread 0x2b9c5f2a7700 (LWP 21335) exited] 00000010 ccid_usb.c:660:WriteUSB() write failed (3/52): -4 No such device 00000003 ccid_usb.c:742:CloseUSB() Closing USB device: 3/52 00000001 ccid_usb.c:763:CloseUSB() Last slot closed. Release resources 00000017 readerfactory.c:905:RFUnloadReader() Unloading reader driver. Program received signal SIGSEGV, Segmentation fault. [Switching to Thread 0x2b9c5eea5700 (LWP 21333)] 0x00002b9c5ea9c67b in ?? () (gdb) bt #0 0x00002b9c5ea9c67b in ?? () #1 0x0000000000000000 in ?? () (gdb) That 2bc9c5ea9c67b address looks like it belongs to a stack according to /proc/$$/maps. I wonder whether the occurrence of SIGUSR1 indicates usage of async-signal-unsafe constructs within the signal handler.
Created attachment 902987 [details] strace -f of same Apart from the SEGV bug, note the poll/recvmsg loop, of which I elided a few tens of thousands of lines. That can't be good for CPU usage.
I suspect the poll/recvmsg system calls comes from libusb. What version of libusb is the libccid driver using?
This is fairly up-to-date f19, so libusb-0.1.5-3.fc19.x86_64
It should be libusb-1.0.x or libusbx-1.0.x
% rpm -qa libusb\* libusbx-1.0.16-3.fc19.x86_64 libusbx-devel-1.0.16-3.fc19.x86_64 libusbx-1.0.16-3.fc19.i686 libusbx-debuginfo-1.0.16-3.fc19.x86_64 libusb1-debuginfo-1.0.9-0.6.rc1.fc17.x86_64 libusb-0.1.5-3.fc19.x86_64
I've just tried with a yubikey neo and tried the exact same steps on Comment 5. There was no crash and the output of pkcs11-tool -L was: Slot 1 (0x1): Yubico Yubikey NEO OTP+CCID 00 00 token label : PIV_II (PIV Card Holder pin) token manufacturer : piv_II token model : PKCS#15 emulated token flags : rng, login required, PIN initialized, token initialized hardware version : 0.0 firmware version : 0.0 serial num : 00000000 I tried on the latest f20 packages.
So I believe the catch is in your "Note this machine also has a TPM and related daemons running". Could you try disabling all of those daemons, and removing the additional hardware (if possible). Then try the reproducer that you sent, each time with different hardware attached, or different daemons started.
Could you also try using pcsc-lite (and ccid) from f20? It could have been an issue already solved in f20. http://koji.fedoraproject.org/koji/buildinfo?buildID=472673 http://koji.fedoraproject.org/koji/buildinfo?buildID=521052
I get very similar (the same?) crash with hard-drive connected via USB: 0) start pcscd service 1) plug in or plug out USB hard-drive The gdb and valgrind show no useful backtrace. Versions (Fedora 20, tested both: updates and updates-testing): pcsc-lite-1.8.10-1.fc20.x86_64 pcsc-lite-1.8.10-2.fc20.x86_64 gdb: 00000000 ifdhandler.c:117:CreateChannelByNameOrChannel() failed 00000075 readerfactory.c:1020:RFInitializeReader() Open Port 0x200000 Failed (usb:0a5c/5801:libudev:0:/dev/bus/usb/005/002) 00000034 readerfactory.c:312:RFAddReader() Broadcom Corp 5880 [Broadcom USH w/swipe sensor] (0123456789ABCD) init failed. [New Thread 0x7fd686d21700 (LWP 20301)] 03044691 ccid_usb.c:1142:ControlUSB() control failed (5/2): -7 Resource temporarily unavailable 00119962 commands.c:1119:CmdGetSlotStatus Hardware error 00001744 commands.c:1119:CmdGetSlotStatus Hardware error 00001998 commands.c:1119:CmdGetSlotStatus Hardware error 00000025 ifdhandler.c:158:CreateChannelByNameOrChannel() failed 00000027 readerfactory.c:1020:RFInitializeReader() Open Port 0x200001 Failed (usb:0a5c/5801:libudev:1:/dev/bus/usb/005/002) 00000012 readerfactory.c:312:RFAddReader() Broadcom Corp 5880 [Contacted SmartCard] (0123456789ABCD) init failed. 00003607 hotplug_libudev.c:391:HPAddDevice() Failed adding USB device: Broadcom Corp 5880 [New Thread 0x7fd686520700 (LWP 20302)] Program received signal SIGSEGV, Segmentation fault. [Switching to Thread 0x7fd686d21700 (LWP 20301)] 0x0000003de520f3bc in ?? () (gdb) bt #0 0x0000003de520f3bc in ?? () #1 0x00000000007ffe20 in ?? () #2 0x00007fd686d21700 in ?? () #3 0x0000000100000005 in ?? () #4 0x0001000100000004 in ?? () #5 0x00007fd686521000 in ?? () #6 0x6523781654313c00 in ?? () #7 0x00007fd686d21700 in ?? () #8 0x00007fd686d21700 in ?? () #9 0x0000000000000000 in ?? () (gdb) valgrind: ==20325== Memcheck, a memory error detector ==20325== Copyright (C) 2002-2013, and GNU GPL'd, by Julian Seward et al. ==20325== Using Valgrind-3.9.0 and LibVEX; rerun with -h for copyright info ==20325== Command: /usr/sbin/pcscd --foreground --auto-exit ==20325== 00000000 ifdhandler.c:117:CreateChannelByNameOrChannel() failed 00048779 readerfactory.c:1020:RFInitializeReader() Open Port 0x200000 Failed (usb:0a5c/5801:libudev:0:/dev/bus/usb/005/002) 00002331 readerfactory.c:312:RFAddReader() Broadcom Corp 5880 [Broadcom USH w/swipe sensor] (0123456789ABCD) init failed. 03782150 ccid_usb.c:1142:ControlUSB() control failed (5/2): -7 Resource temporarily unavailable 00192888 commands.c:1119:CmdGetSlotStatus Hardware error 00005267 commands.c:1119:CmdGetSlotStatus Hardware error 00002974 commands.c:1119:CmdGetSlotStatus Hardware error 00000930 ifdhandler.c:158:CreateChannelByNameOrChannel() failed 00002962 readerfactory.c:1020:RFInitializeReader() Open Port 0x200001 Failed (usb:0a5c/5801:libudev:1:/dev/bus/usb/005/002) 00000260 readerfactory.c:312:RFAddReader() Broadcom Corp 5880 [Contacted SmartCard] (0123456789ABCD) init failed. 00012409 hotplug_libudev.c:391:HPAddDevice() Failed adding USB device: Broadcom Corp 5880 ==20325== Thread 2: ==20325== Jump to the invalid address stated on the next line ==20325== at 0x3DE520F3BC: ??? ==20325== by 0x7FFE1F: ??? ==20325== Address 0x3de520f3bc is not stack'd, malloc'd or (recently) free'd ==20325== ==20325== ==20325== Process terminating with default action of signal 11 (SIGSEGV): dumping core ==20325== Bad permissions for mapped region at address 0x3DE520F3BC ==20325== at 0x3DE520F3BC: ??? ==20325== by 0x7FFE1F: ??? ==20325==
There seems to be some issue with RFUnloadReader(). In the attached log I see two loads (on unsuccessful) and two unloads. The first unload of the unsuccessfully loaded structure continues ok, while the latter crashes while trying to unload the module. I'll check it further. 00000008 hotplug_libudev.c:312:HPAddDevice() Adding USB device: Yubico Yubikey NEO OTP+CCID 00000035 readerfactory.c:978:RFInitializeReader() Attempting startup of Yubico Yubikey NEO OTP+CCID 00 00 using /usr/lib64/pcsc/drivers/ifd-ccid.bundle/Contents/Linux/libccid.so 00000103 readerfactory.c:868:RFBindFunctions() Loading IFD Handler 3.0 00000045 ifdhandler.c:117:CreateChannelByNameOrChannel() failed 00000004 readerfactory.c:1009:RFInitializeReader() Open Port 0x200000 Failed (usb:1050/0111:libudev:0:/dev/bus/usb/003/049) 00000010 readerfactory.c:312:RFAddReader() Yubico Yubikey NEO OTP+CCID init failed. 00000005 readerfactory.c:529:RFRemoveReader() UnrefReader() count was: 1 00000003 hotplug_libudev.c:312:HPAddDevice() Adding USB device: Yubico Yubikey NEO OTP+CCID 00000045 readerfactory.c:978:RFInitializeReader() Attempting startup of Yubico Yubikey NEO OTP+CCID 00 00 using /usr/lib64/pcsc/drivers/ifd-ccid.bundle/Contents/Linux/libccid.so 00000082 readerfactory.c:868:RFBindFunctions() Loading IFD Handler 3.0 00000012 ifdhandler.c:1840:init_driver() Driver version: 1.4.10 00000006 readerfactory.c:1029:RFUnInitializeReader() Attempting shutdown of Yubico Yubikey NEO OTP+CCID 00 00. 00000005 ifdhandler.c:249:IFDHCloseChannel() usb:1050/0111:libudev:1:/dev/bus/usb/003/049 (lun: 0) 00000014 -> 000000 63 00 00 00 00 00 08 00 00 00 00000014 ccid_usb.c:660:WriteUSB() write failed (3/49): -4 No such device 00000003 ccid_usb.c:742:CloseUSB() Closing USB device: 3/49 00000001 ccid_usb.c:763:CloseUSB() Last slot closed. Release resources 00000022 readerfactory.c:905:RFUnloadReader() Unloading reader driver. 00000061 hotplug_libudev.c:587:HPEstablishUSBNotifications() Device removed
(In reply to František Dvořák from comment #21) > I get very similar (the same?) crash with hard-drive connected via USB: > > 0) start pcscd service > 1) plug in or plug out USB hard-drive > > The gdb and valgrind show no useful backtrace. It's not easy to tell whether they are the same issue of not. Could you open a different bug and provide your full log there?
(In reply to Nikos Mavrogiannopoulos from comment #22) > There seems to be some issue with RFUnloadReader(). > > In the attached log I see two loads (on unsuccessful) and two unloads. The > first unload of the unsuccessfully loaded structure continues ok, while the > latter crashes while trying to unload the module. I'll check it further. I only find 1 log for RFUnloadReader(), not 2. Also the loading of the library did not fail. The initialisation of the reader failed. But the library had to be unloaded.
In the attached log there are: 00000005 readerfactory.c:529:RFRemoveReader() UnrefReader() count was: 1 00000001 readerfactory.c:1029:RFUnInitializeReader() Attempting shutdown of Yubico Yubikey NEO OTP+CCID 00 00. 00000002 readerfactory.c:905:RFUnloadReader() Unloading reader driver. and one before the crash: 00000003 ccid_usb.c:742:CloseUSB() Closing USB device: 3/49 00000001 ccid_usb.c:763:CloseUSB() Last slot closed. Release resources 00000022 readerfactory.c:905:RFUnloadReader() Unloading reader driver. Given the unknown address the crash occurred, it seems like dlclose() tried to jump to elf deinitialization functions that were not there.
OK I see the 2 calls to RFUnloadReader() in https://bugzilla.redhat.com/attachment.cgi?id=902524 The library has been loaded twice so need to be unloaded twice. The dlclose() is done just after the log "Unloading reader driver.". Since we get a new log line after that it looks like the dlclose() did not fail. The libccid library do not have deinitialization functions. I can't explain the crash :-(
Should we have two of these? 00000006 hotplug_libudev.c:513:HPRescanUsbBus() Removing USB device[0]: Yubico Yubikey NEO OTP+CCID at /dev/bus/usb/003/049 00000004 hotplug_libudev.c:513:HPRescanUsbBus() Removing USB device[1]: Yubico Yubikey NEO OTP+CCID at /dev/bus/usb/003/049 Given that the status for one of the is READER_FAILED? As far as I understand in the case where RFAddReader() failed, the status should was set to READER_FAILED. However HPRescanUsbBus() sets everything to ABSENT and tries to remove the already removed that was failed. Is that the intention as well? I still cannot see how that could lead to a crash though.
Can you use pcsc-lite 1.8.12 and check the problem is still present? This version has a new hotplug code with races removed. http://ludovicrousseau.blogspot.fr/2014/09/new-version-of-pcsc-lite-1812.html
pcsc-lite-1.8.12-1.fc21 has been submitted as an update for Fedora 21. https://admin.fedoraproject.org/updates/pcsc-lite-1.8.12-1.fc21
pcsc-lite-1.8.12-1.fc21 has been pushed to the Fedora 21 stable repository. If problems still persist, please make note of it in this bug report.
This message is a notice that Fedora 19 is now at end of life. Fedora has stopped maintaining and issuing updates for Fedora 19. It is Fedora's policy to close all bug reports from releases that are no longer maintained. Approximately 4 (four) weeks from now this bug will be closed as EOL if it remains open with a Fedora 'version' of '19'. Package Maintainer: If you wish for this bug to remain open because you plan to fix it in a currently maintained version, simply change the 'version' to a later Fedora version. Thank you for reporting this issue and we are sorry that we were not able to fix it before Fedora 19 is end of life. If you would still like to see this bug fixed and are able to reproduce it against a later version of Fedora, you are encouraged change the 'version' to a later Fedora version prior this bug is closed as described in the policy above. Although we aim to fix as many bugs as possible during every release's lifetime, sometimes those efforts are overtaken by events. Often a more recent Fedora release includes newer upstream software that fixes bugs or makes them obsolete.
Fedora 19 changed to end-of-life (EOL) status on 2015-01-06. Fedora 19 is no longer maintained, which means that it will not receive any further security or bug fix updates. As a result we are closing this bug. If you can reproduce this bug against a currently maintained version of Fedora please feel free to reopen this bug against that version. If you are unable to reopen this bug, please file a new report against the current release. If you experience problems, please add a comment to this bug. Thank you for reporting this bug and we are sorry it could not be fixed.
Hello, i'm new here and also have exactly the same problems and messages in /var/log/messages as Frank when i plug <-> unplug my card reader. Sometimes i need to plug <-> unplug it more then once to get it crashed but in genereal it's once. I have a CentOS 6.6 running with pcsc-light 1.8.13. I have libusb1-1.0.9 I face exactly the same problems when i tail /var/log/messages I use a Gemalto Reader. When i plug it in i see messages from Kernel telling me that the reader is connected and i see: idVendor: 08e6 idProduct: 3478 I use also a IDPrime Card from Gemalto. So now my reader is connected and i put the card in. Now i remove the card and i see in /var/log/messages multiple errors like: pcscd[15616]: 00008981 commands.c:1289:CCID_Receive error on byte 3 pcscd[15616]: 00000006 ifdwrapper.c:550:IFDTransmit() Card not transacted: 612 Now i put the card back in. Now i unplug the reader from usb and plug it in again. I see again Kernel messages telling me that my reader is pluged in getting a new usb port #. But then i see pcscd: readerfactory.c:206:RFAddReader() Duplicate Reader found After a while and after some plug <-> unplug later i also see this entries: pcscd[15616]: 12177035 readerfactory.c:1104:RFAddReaderHandle() Too many handles opened, exceeding configured max (200) Any help? Suggestions?
Hello, i did some further tests and used a differend card reader. Now im using a ReinertSCT cyverJack reader. I get this informations from Kernel idVendor: 0c4b idProduct: 0400 For sure i never got a "Duplicate Reader found" error even if i plug <-> unplug the reader very fast or in different USB-Ports. Also my applications i run (mostly firefox) and where i use a smartcard to authenticate to my application (mutual TLS - thats why i need smartcard) are stable even to plug <-> unplug. But what i still get are errors like: winscard.c:1635:SCardTransmit() Card not transcated And i also managed to get this error: eventhandler.c:336:EHStatusHandlerThread() Error connection to: Reiner SCT cyperJack. Thus i looks quite good using the ReinerSCT But when i use the Gemalto/Gemplus Reader then the problems are much more bigger and visible.
(In reply to Markus from comment #33) > Hello, > > i'm new here and also have exactly the same problems and messages in > /var/log/messages as Frank when i plug <-> unplug my card reader. > Sometimes i need to plug <-> unplug it more then once to get it crashed but > in genereal it's once. > > I have a CentOS 6.6 running with pcsc-light 1.8.13. > I have libusb1-1.0.9 This bug is for the fedora system. For bugs in centos please use the centos bugzilla.