Bug#767862: pcscd: Socket activation not working on first try

Laurent Bigonville Wed, 05 Nov 2014 03:04:10 -0800

On Mon, 03 Nov 2014 20:33:01 +0100 Ludovic Rousseau
<ludovic.rouss...@gmail.com> wrote:
[...]
> 
> Edit the file /lib/systemd/system/pcscd.service and add "--debug" to
> the line: ExecStart=/usr/local/sbin/pcscd --foreground --auto-exit
> 
> This should generate much more pcscd debug messages.


I've attached the log here.

You can see a first call to gpg --card-status that fails and then a 2nd
one 1 min later.

Cheers,

Laurent Bigonville

-- Logs begin at ven 2014-08-22 18:56:15 CEST, end at mer 2014-11-05 11:56:38 CET. --
nov 05 11:05:37 soldur pcscd[3716]: 00000000 utils.c:87:GetDaemonPid() Can't open /var/run/pcscd/pcscd.pid: No such file or directory
nov 05 11:05:37 soldur pcscd[3716]: 00007192 ifdhandler.c:130:CreateChannelByNameOrChannel() failed
nov 05 11:05:37 soldur pcscd[3716]: 00000010 readerfactory.c:1046:RFInitializeReader() Open Port 0x200000 Failed (usb:0a5c/5802:libudev:0:/dev/bus/usb/004/003)
nov 05 11:05:37 soldur pcscd[3716]: 00000002 readerfactory.c:338:RFAddReader() Broadcom Corp 5880 [Broadcom USH w/touch sensor] (0123456789ABCD) init failed.
nov 05 11:55:40 soldur pcscd[4674]: 00000000 debuglog.c:295:DebugLogSetLevel() debug level=debug
nov 05 11:55:40 soldur pcscd[4674]: 00000022 pcscdaemon.c:375:main() Started by systemd
nov 05 11:55:40 soldur pcscd[4674]: 00000139 utils.c:87:GetDaemonPid() Can't open /var/run/pcscd/pcscd.pid: No such file or directory
nov 05 11:55:40 soldur pcscd[4674]: 00000066 configfile.l:286:DBGetReaderListDir() Parsing conf directory: /etc/reader.conf.d
nov 05 11:55:40 soldur pcscd[4674]: 00000233 configfile.l:320:DBGetReaderListDir() Skipping non regular file: ..
nov 05 11:55:40 soldur pcscd[4674]: 00000010 configfile.l:358:DBGetReaderList() Parsing conf file: /etc/reader.conf.d/libccidtwin
nov 05 11:55:40 soldur pcscd[4674]: 00000284 configfile.l:320:DBGetReaderListDir() Skipping non regular file: .
nov 05 11:55:40 soldur pcscd[4674]: 00000009 pcscdaemon.c:571:main() pcsc-lite 1.8.12 daemon ready.
nov 05 11:55:40 soldur pcscd[4674]: 00001611 winscard_msg_srv.c:256:ProcessEventsServer() Common channel packet arrival
nov 05 11:55:40 soldur pcscd[4674]: 00000013 winscard_msg_srv.c:268:ProcessEventsServer() ProcessCommonChannelRequest detects: 4
nov 05 11:55:40 soldur pcscd[4674]: 00000004 pcscdaemon.c:137:SVCServiceRunLoop() A new context thread creation is requested: 4
nov 05 11:55:40 soldur pcscd[4674]: 00000096 winscard_svc.c:334:ContextThread() Authorized PC/SC client
nov 05 11:55:40 soldur pcscd[4674]: 00000010 winscard_svc.c:338:ContextThread() Thread is started: dwClientID=4, threadContext @0x12a2330
nov 05 11:55:40 soldur pcscd[4674]: 00000026 winscard_svc.c:356:ContextThread() Received command: CMD_VERSION from client 4
nov 05 11:55:40 soldur pcscd[4674]: 00000005 winscard_svc.c:368:ContextThread() Client is protocol version 4:3
nov 05 11:55:40 soldur pcscd[4674]: 00000003 winscard_svc.c:388:ContextThread() CMD_VERSION rv=0x0 for client 4
nov 05 11:55:40 soldur pcscd[4674]: 00000105 winscard_svc.c:356:ContextThread() Received command: ESTABLISH_CONTEXT from client 4
nov 05 11:55:40 soldur pcscd[4674]: 00000011 winscard.c:219:SCardEstablishContext() Establishing Context: 0x3BABAFD3
nov 05 11:55:40 soldur pcscd[4674]: 00000003 winscard_svc.c:449:ContextThread() ESTABLISH_CONTEXT rv=0x0 for client 4
nov 05 11:55:40 soldur pcscd[4674]: 00000027 winscard_svc.c:356:ContextThread() Received command: CMD_GET_READERS_STATE from client 4
nov 05 11:55:40 soldur pcscd[4674]: 00000057 winscard_svc.c:356:ContextThread() Received command: RELEASE_CONTEXT from client 4
nov 05 11:55:40 soldur pcscd[4674]: 00000006 winscard.c:230:SCardReleaseContext() Releasing Context: 0x3BABAFD3
nov 05 11:55:40 soldur pcscd[4674]: 00000004 winscard_svc.c:464:ContextThread() RELEASE_CONTEXT rv=0x0 for client 4
nov 05 11:55:40 soldur pcscd[4674]: 00000021 winscard_svc.c:348:ContextThread() Client die: 4
nov 05 11:55:40 soldur pcscd[4674]: 00000011 winscard_svc.c:981:MSGCleanupClient() Thread is stopping: dwClientID=4, threadContext @0x12a2330
nov 05 11:55:40 soldur pcscd[4674]: 00000004 winscard_svc.c:987:MSGCleanupClient() Freeing SCONTEXT @0x12a2330
nov 05 11:55:40 soldur pcscd[4674]: 00000005 winscard_svc.c:1002:MSGCleanupClient() Starting suicide alarm in 60 seconds
nov 05 11:55:40 soldur pcscd[4674]: 00000754 hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/001/001
nov 05 11:55:40 soldur pcscd[4674]: 00000182 hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0003, path: /dev/bus/usb/002/001
nov 05 11:55:40 soldur pcscd[4674]: 00000175 hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/003/001
nov 05 11:55:40 soldur pcscd[4674]: 00000120 hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/003/001
nov 05 11:55:40 soldur pcscd[4674]: 00000135 hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x8087, PID: 0x0024, path: /dev/bus/usb/003/002
nov 05 11:55:40 soldur pcscd[4674]: 00000095 hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x05E3, PID: 0x0608, path: /dev/bus/usb/003/003
nov 05 11:55:40 soldur pcscd[4674]: 00000066 hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x04D9, PID: 0x0462, path: /dev/bus/usb/003/006
nov 05 11:55:40 soldur pcscd[4674]: 00000079 hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x05E3, PID: 0x0608, path: /dev/bus/usb/003/003
nov 05 11:55:40 soldur pcscd[4674]: 00000064 hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x04D9, PID: 0x1603, path: /dev/bus/usb/003/007
nov 05 11:55:40 soldur pcscd[4674]: 00000065 hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x04D9, PID: 0x1603, path: /dev/bus/usb/003/007
nov 05 11:55:40 soldur pcscd[4674]: 00000074 hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x05E3, PID: 0x0608, path: /dev/bus/usb/003/003
nov 05 11:55:40 soldur pcscd[4674]: 00000061 hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x8087, PID: 0x0024, path: /dev/bus/usb/003/002
nov 05 11:55:40 soldur pcscd[4674]: 00000059 hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x0C45, PID: 0x648B, path: /dev/bus/usb/003/005
nov 05 11:55:40 soldur pcscd[4674]: 00000072 hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x0C45, PID: 0x648B, path: /dev/bus/usb/003/005
nov 05 11:55:40 soldur pcscd[4674]: 00000060 hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x8087, PID: 0x0024, path: /dev/bus/usb/003/002
nov 05 11:55:40 soldur pcscd[4674]: 00000098 hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/004/001
nov 05 11:55:40 soldur pcscd[4674]: 00000061 hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x1D6B, PID: 0x0002, path: /dev/bus/usb/004/001
nov 05 11:55:40 soldur pcscd[4674]: 00000057 hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x8087, PID: 0x0024, path: /dev/bus/usb/004/002
nov 05 11:55:40 soldur pcscd[4674]: 00000071 hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x0A5C, PID: 0x5802, path: /dev/bus/usb/004/003
nov 05 11:55:40 soldur pcscd[4674]: 00000005 hotplug_libudev.c:438:HPAddDevice() Adding USB device: Broadcom Corp 5880
nov 05 11:55:40 soldur pcscd[4674]: 00000036 readerfactory.c:1015:RFInitializeReader() Attempting startup of Broadcom Corp 5880 [Broadcom USH w/touch sensor] (0123456789ABCD) 00 00 using /usr/lib/pcsc/drivers/ifd-ccid.bundle/Contents/Linux/libccid.so
nov 05 11:55:40 soldur pcscd[4674]: 00001227 readerfactory.c:900:RFBindFunctions() Loading IFD Handler 3.0
nov 05 11:55:40 soldur pcscd[4674]: 00000029 ifdhandler.c:1927:init_driver() Driver version: 1.4.18
nov 05 11:55:40 soldur pcscd[4674]: 00000502 ifdhandler.c:1944:init_driver() LogLevel: 0x0003
nov 05 11:55:40 soldur pcscd[4674]: 00000005 ifdhandler.c:1955:init_driver() DriverOptions: 0x0000
nov 05 11:55:40 soldur pcscd[4674]: 00000091 ifdhandler.c:96:CreateChannelByNameOrChannel() Lun: 0, device: usb:0a5c/5802:libudev:0:/dev/bus/usb/004/003
nov 05 11:55:40 soldur pcscd[4674]: 00000012 ccid_usb.c:284:OpenUSBByName() Using: /usr/lib/pcsc/drivers/ifd-ccid.bundle/Contents/Info.plist
nov 05 11:55:40 soldur pcscd[4674]: 00000381 ccid_usb.c:302:OpenUSBByName() ifdManufacturerString: Ludovic Rousseau (ludovic.rouss...@free.fr)
nov 05 11:55:40 soldur pcscd[4674]: 00000004 ccid_usb.c:303:OpenUSBByName() ifdProductString: Generic CCID driver
nov 05 11:55:40 soldur pcscd[4674]: 00000002 ccid_usb.c:304:OpenUSBByName() Copyright: This driver is protected by terms of the GNU Lesser General Public License version 2.1, or (at your option) any later version.
nov 05 11:55:40 soldur pcscd[4674]: 00002141 ccid_usb.c:574:OpenUSBByName() Found interface 0 but expecting 1
nov 05 11:55:40 soldur pcscd[4674]: 00000005 ccid_usb.c:576:OpenUSBByName() Wrong interface for USB device 4/3. Checking next one.
nov 05 11:55:40 soldur pcscd[4674]: 00000067 ccid_usb.c:191:close_libusb_if_needed() libusb_exit
nov 05 11:55:40 soldur pcscd[4674]: 00000053 ccid_usb.c:704:OpenUSBByName() Device not found?
nov 05 11:55:40 soldur pcscd[4674]: 00000004 ifdhandler.c:130:CreateChannelByNameOrChannel() failed
nov 05 11:55:40 soldur pcscd[4674]: 00000003 readerfactory.c:1046:RFInitializeReader() Open Port 0x200000 Failed (usb:0a5c/5802:libudev:0:/dev/bus/usb/004/003)
nov 05 11:55:40 soldur pcscd[4674]: 00000003 readerfactory.c:338:RFAddReader() Broadcom Corp 5880 [Broadcom USH w/touch sensor] (0123456789ABCD) init failed.
nov 05 11:55:40 soldur pcscd[4674]: 00000003 readerfactory.c:561:RFRemoveReader() UnrefReader() count was: 1
nov 05 11:55:40 soldur pcscd[4674]: 00000002 readerfactory.c:1066:RFUnInitializeReader() Attempting shutdown of Broadcom Corp 5880 [Broadcom USH w/touch sensor] (0123456789ABCD) 00 00.
nov 05 11:55:40 soldur pcscd[4674]: 00000002 readerfactory.c:937:RFUnloadReader() Unloading reader driver.
nov 05 11:55:40 soldur pcscd[4674]: 00000097 hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x0A5C, PID: 0x5802, path: /dev/bus/usb/004/003
nov 05 11:55:40 soldur pcscd[4674]: 00000004 hotplug_libudev.c:438:HPAddDevice() Adding USB device: Broadcom Corp 5880
nov 05 11:55:40 soldur pcscd[4674]: 00000032 readerfactory.c:1015:RFInitializeReader() Attempting startup of Broadcom Corp 5880 [Contacted SmartCard] (0123456789ABCD) 00 00 using /usr/lib/pcsc/drivers/ifd-ccid.bundle/Contents/Linux/libccid.so
nov 05 11:55:40 soldur pcscd[4674]: 00000091 readerfactory.c:900:RFBindFunctions() Loading IFD Handler 3.0
nov 05 11:55:40 soldur pcscd[4674]: 00000014 ifdhandler.c:1927:init_driver() Driver version: 1.4.18
nov 05 11:55:40 soldur pcscd[4674]: 00000456 ifdhandler.c:1944:init_driver() LogLevel: 0x0003
nov 05 11:55:40 soldur pcscd[4674]: 00000005 ifdhandler.c:1955:init_driver() DriverOptions: 0x0000
nov 05 11:55:40 soldur pcscd[4674]: 00000087 ifdhandler.c:96:CreateChannelByNameOrChannel() Lun: 0, device: usb:0a5c/5802:libudev:1:/dev/bus/usb/004/003
nov 05 11:55:40 soldur pcscd[4674]: 00000010 ccid_usb.c:284:OpenUSBByName() Using: /usr/lib/pcsc/drivers/ifd-ccid.bundle/Contents/Info.plist
nov 05 11:55:40 soldur pcscd[4674]: 00000420 ccid_usb.c:302:OpenUSBByName() ifdManufacturerString: Ludovic Rousseau (ludovic.rouss...@free.fr)
nov 05 11:55:40 soldur pcscd[4674]: 00000004 ccid_usb.c:303:OpenUSBByName() ifdProductString: Generic CCID driver
nov 05 11:55:40 soldur pcscd[4674]: 00000003 ccid_usb.c:304:OpenUSBByName() Copyright: This driver is protected by terms of the GNU Lesser General Public License version 2.1, or (at your option) any later version.
nov 05 11:55:40 soldur pcscd[4674]: 00002210 ccid_usb.c:596:OpenUSBByName() Found Vendor/Product: 0A5C/5802 (Broadcom Corp 5880)
nov 05 11:55:40 soldur pcscd[4674]: 00000004 ccid_usb.c:598:OpenUSBByName() Using USB bus/device: 4/3
nov 05 11:55:40 soldur pcscd[4674]: 00000003 ccid_usb.c:650:OpenUSBByName() bNumDataRatesSupported is 0
nov 05 11:55:40 soldur pcscd[4674]: 00085162 ifdhandler.c:375:IFDHGetCapabilities() tag: 0xFB3, usb:0a5c/5802:libudev:1:/dev/bus/usb/004/003 (lun: 0)
nov 05 11:55:40 soldur pcscd[4674]: 00000025 readerfactory.c:358:RFAddReader() Using the reader polling thread
nov 05 11:55:40 soldur pcscd[4674]: 00002627 ifdhandler.c:375:IFDHGetCapabilities() tag: 0xFAE, usb:0a5c/5802:libudev:1:/dev/bus/usb/004/003 (lun: 0)
nov 05 11:55:40 soldur pcscd[4674]: 00000015 ifdhandler.c:463:IFDHGetCapabilities() Reader supports 1 slot(s)
nov 05 11:55:40 soldur pcscd[4674]: 00000151 hotplug_libudev.c:299:get_driver() Looking for a driver for VID: 0x8087, PID: 0x0024, path: /dev/bus/usb/004/002
nov 05 11:55:40 soldur pcscd[4674]: 00005195 ifdhandler.c:1139:IFDHPowerICC() action: PowerUp, usb:0a5c/5802:libudev:1:/dev/bus/usb/004/003 (lun: 0)
nov 05 11:55:40 soldur pcscd[4674]: 00046137 eventhandler.c:292:EHStatusHandlerThread() powerState: POWER_STATE_POWERED
nov 05 11:55:40 soldur pcscd[4674]: 00000025 Card ATR: 3B DA 18 FF 81 B1 FE 75 1F 03 00 31 C5 73 C0 01 40 00 90 00 0C
nov 05 11:55:46 soldur pcscd[4674]: 05012869 ifdhandler.c:1139:IFDHPowerICC() action: PowerDown, usb:0a5c/5802:libudev:1:/dev/bus/usb/004/003 (lun: 0)
nov 05 11:55:46 soldur pcscd[4674]: 00002238 eventhandler.c:481:EHStatusHandlerThread() powerState: POWER_STATE_UNPOWERED
nov 05 11:56:37 soldur pcscd[4674]: 51469886 winscard_msg_srv.c:256:ProcessEventsServer() Common channel packet arrival
nov 05 11:56:37 soldur pcscd[4674]: 00000040 winscard_msg_srv.c:268:ProcessEventsServer() ProcessCommonChannelRequest detects: 14
nov 05 11:56:37 soldur pcscd[4674]: 00000009 pcscdaemon.c:137:SVCServiceRunLoop() A new context thread creation is requested: 14
nov 05 11:56:37 soldur pcscd[4674]: 00000092 winscard_svc.c:334:ContextThread() Authorized PC/SC client
nov 05 11:56:37 soldur pcscd[4674]: 00000014 winscard_svc.c:338:ContextThread() Thread is started: dwClientID=14, threadContext @0x12a2330
nov 05 11:56:37 soldur pcscd[4674]: 00000049 winscard_svc.c:356:ContextThread() Received command: CMD_VERSION from client 14
nov 05 11:56:37 soldur pcscd[4674]: 00000013 winscard_svc.c:368:ContextThread() Client is protocol version 4:3
nov 05 11:56:37 soldur pcscd[4674]: 00000007 winscard_svc.c:388:ContextThread() CMD_VERSION rv=0x0 for client 14
nov 05 11:56:37 soldur pcscd[4674]: 00000074 winscard_svc.c:356:ContextThread() Received command: ESTABLISH_CONTEXT from client 14
nov 05 11:56:37 soldur pcscd[4674]: 00000014 winscard.c:219:SCardEstablishContext() Establishing Context: 0x2A141D69
nov 05 11:56:37 soldur pcscd[4674]: 00000006 winscard_svc.c:449:ContextThread() ESTABLISH_CONTEXT rv=0x0 for client 14
nov 05 11:56:37 soldur pcscd[4674]: 00000058 winscard_svc.c:356:ContextThread() Received command: CMD_GET_READERS_STATE from client 14
nov 05 11:56:37 soldur pcscd[4674]: 00000045 winscard_svc.c:356:ContextThread() Received command: CMD_GET_READERS_STATE from client 14
nov 05 11:56:37 soldur pcscd[4674]: 00000096 winscard_svc.c:356:ContextThread() Received command: CONNECT from client 14
nov 05 11:56:37 soldur pcscd[4674]: 00000011 winscard_svc.c:487:ContextThread() Authorized client for 'Broadcom Corp 5880 [Contacted SmartCard] (0123456789ABCD) 00 00'
nov 05 11:56:37 soldur pcscd[4674]: 00000006 winscard.c:261:SCardConnect() Attempting Connect to Broadcom Corp 5880 [Contacted SmartCard] (0123456789ABCD) 00 00 using protocol: 3
nov 05 11:56:37 soldur pcscd[4674]: 00000008 readerfactory.c:771:RFReaderInfo() RefReader() count was: 1
nov 05 11:56:37 soldur pcscd[4674]: 00002516 ifdhandler.c:1139:IFDHPowerICC() action: PowerUp, usb:0a5c/5802:libudev:1:/dev/bus/usb/004/003 (lun: 0)
nov 05 11:56:37 soldur pcscd[4674]: 00047046 winscard.c:336:SCardConnect() power up complete.
nov 05 11:56:37 soldur pcscd[4674]: 00000026 Card ATR: 3B DA 18 FF 81 B1 FE 75 1F 03 00 31 C5 73 C0 01 40 00 90 00 0C
nov 05 11:56:37 soldur pcscd[4674]: 00000007 winscard.c:356:SCardConnect() powerState: POWER_STATE_INUSE
nov 05 11:56:37 soldur pcscd[4674]: 00000008 prothandler.c:113:PHSetProtocol() Attempting PTS to T=1
nov 05 11:56:37 soldur pcscd[4674]: 00000018 ifdhandler.c:682:IFDHSetProtocolParameters() protocol T=1, usb:0a5c/5802:libudev:1:/dev/bus/usb/004/003 (lun: 0)
nov 05 11:56:37 soldur pcscd[4674]: 00000007 ifdhandler.c:2064:extra_egt() Extra EGT patch applied
nov 05 11:56:37 soldur pcscd[4674]: 00052438 winscard.c:435:SCardConnect() Active Protocol: T=1
nov 05 11:56:37 soldur pcscd[4674]: 00000040 winscard.c:455:SCardConnect() hCard Identity: 780afc8d
nov 05 11:56:37 soldur pcscd[4674]: 00000025 winscard.c:516:SCardConnect() UnrefReader() count was: 2
nov 05 11:56:37 soldur pcscd[4674]: 00000009 winscard_svc.c:501:ContextThread() CONNECT rv=0x0 for client 14
nov 05 11:56:37 soldur pcscd[4674]: 00000086 winscard_svc.c:356:ContextThread() Received command: CMD_GET_READERS_STATE from client 14
nov 05 11:56:37 soldur pcscd[4674]: 00000045 winscard_svc.c:356:ContextThread() Received command: STATUS from client 14
nov 05 11:56:37 soldur pcscd[4674]: 00000014 readerfactory.c:798:RFReaderInfoById() RefReader() count was: 1
nov 05 11:56:37 soldur pcscd[4674]: 00000006 winscard.c:1317:SCardStatus() UnrefReader() count was: 2
nov 05 11:56:37 soldur pcscd[4674]: 00000006 winscard_svc.c:609:ContextThread() STATUS rv=0x0 for client 14
nov 05 11:56:37 soldur pcscd[4674]: 00000095 winscard_svc.c:356:ContextThread() Received command: TRANSMIT from client 14
nov 05 11:56:37 soldur pcscd[4674]: 00000026 readerfactory.c:798:RFReaderInfoById() RefReader() count was: 1
nov 05 11:56:37 soldur pcscd[4674]: 00000007 winscard.c:1613:SCardTransmit() Send Protocol: T=1
nov 05 11:56:37 soldur pcscd[4674]: 00000009 ifdhandler.c:1283:IFDHTransmitToICC() usb:0a5c/5802:libudev:1:/dev/bus/usb/004/003 (lun: 0)
nov 05 11:56:37 soldur pcscd[4674]: 00016568 winscard.c:1658:SCardTransmit() UnrefReader() count was: 2
nov 05 11:56:37 soldur pcscd[4674]: 00000038 winscard_svc.c:656:ContextThread() TRANSMIT rv=0x0 for client 14
nov 05 11:56:37 soldur pcscd[4674]: 00000139 winscard_svc.c:356:ContextThread() Received command: TRANSMIT from client 14
nov 05 11:56:37 soldur pcscd[4674]: 00000021 readerfactory.c:798:RFReaderInfoById() RefReader() count was: 1
nov 05 11:56:37 soldur pcscd[4674]: 00000018 winscard.c:1613:SCardTransmit() Send Protocol: T=1
nov 05 11:56:37 soldur pcscd[4674]: 00000009 ifdhandler.c:1283:IFDHTransmitToICC() usb:0a5c/5802:libudev:1:/dev/bus/usb/004/003 (lun: 0)
nov 05 11:56:37 soldur pcscd[4674]: 00011349 winscard.c:1658:SCardTransmit() UnrefReader() count was: 2
nov 05 11:56:37 soldur pcscd[4674]: 00000031 winscard_svc.c:656:ContextThread() TRANSMIT rv=0x0 for client 14
nov 05 11:56:37 soldur pcscd[4674]: 00000101 winscard_svc.c:356:ContextThread() Received command: TRANSMIT from client 14
nov 05 11:56:37 soldur pcscd[4674]: 00000019 readerfactory.c:798:RFReaderInfoById() RefReader() count was: 1
nov 05 11:56:37 soldur pcscd[4674]: 00000007 winscard.c:1613:SCardTransmit() Send Protocol: T=1
nov 05 11:56:37 soldur pcscd[4674]: 00000007 ifdhandler.c:1283:IFDHTransmitToICC() usb:0a5c/5802:libudev:1:/dev/bus/usb/004/003 (lun: 0)
nov 05 11:56:37 soldur pcscd[4674]: 00009080 winscard.c:1658:SCardTransmit() UnrefReader() count was: 2
nov 05 11:56:37 soldur pcscd[4674]: 00000034 winscard_svc.c:656:ContextThread() TRANSMIT rv=0x0 for client 14
nov 05 11:56:37 soldur pcscd[4674]: 00000147 winscard_svc.c:356:ContextThread() Received command: TRANSMIT from client 14
nov 05 11:56:37 soldur pcscd[4674]: 00000035 readerfactory.c:798:RFReaderInfoById() RefReader() count was: 1
nov 05 11:56:37 soldur pcscd[4674]: 00000007 winscard.c:1613:SCardTransmit() Send Protocol: T=1
nov 05 11:56:37 soldur pcscd[4674]: 00000006 ifdhandler.c:1283:IFDHTransmitToICC() usb:0a5c/5802:libudev:1:/dev/bus/usb/004/003 (lun: 0)
nov 05 11:56:37 soldur pcscd[4674]: 00013116 winscard.c:1658:SCardTransmit() UnrefReader() count was: 2
nov 05 11:56:37 soldur pcscd[4674]: 00000042 winscard_svc.c:656:ContextThread() TRANSMIT rv=0x0 for client 14
nov 05 11:56:37 soldur pcscd[4674]: 00000122 winscard_svc.c:356:ContextThread() Received command: TRANSMIT from client 14
nov 05 11:56:37 soldur pcscd[4674]: 00000024 readerfactory.c:798:RFReaderInfoById() RefReader() count was: 1
nov 05 11:56:37 soldur pcscd[4674]: 00000007 winscard.c:1613:SCardTransmit() Send Protocol: T=1
nov 05 11:56:37 soldur pcscd[4674]: 00000009 ifdhandler.c:1283:IFDHTransmitToICC() usb:0a5c/5802:libudev:1:/dev/bus/usb/004/003 (lun: 0)
nov 05 11:56:37 soldur pcscd[4674]: 00063789 winscard.c:1658:SCardTransmit() UnrefReader() count was: 2
nov 05 11:56:37 soldur pcscd[4674]: 00000035 winscard_svc.c:656:ContextThread() TRANSMIT rv=0x0 for client 14
nov 05 11:56:37 soldur pcscd[4674]: 00000159 winscard_svc.c:356:ContextThread() Received command: TRANSMIT from client 14
nov 05 11:56:37 soldur pcscd[4674]: 00000023 readerfactory.c:798:RFReaderInfoById() RefReader() count was: 1
nov 05 11:56:37 soldur pcscd[4674]: 00000006 winscard.c:1613:SCardTransmit() Send Protocol: T=1
nov 05 11:56:37 soldur pcscd[4674]: 00000005 ifdhandler.c:1283:IFDHTransmitToICC() usb:0a5c/5802:libudev:1:/dev/bus/usb/004/003 (lun: 0)
nov 05 11:56:37 soldur pcscd[4674]: 00010826 winscard.c:1658:SCardTransmit() UnrefReader() count was: 2
nov 05 11:56:37 soldur pcscd[4674]: 00000049 winscard_svc.c:656:ContextThread() TRANSMIT rv=0x0 for client 14
nov 05 11:56:37 soldur pcscd[4674]: 00000133 winscard_svc.c:356:ContextThread() Received command: TRANSMIT from client 14
nov 05 11:56:37 soldur pcscd[4674]: 00000023 readerfactory.c:798:RFReaderInfoById() RefReader() count was: 1
nov 05 11:56:37 soldur pcscd[4674]: 00000007 winscard.c:1613:SCardTransmit() Send Protocol: T=1
nov 05 11:56:37 soldur pcscd[4674]: 00000005 ifdhandler.c:1283:IFDHTransmitToICC() usb:0a5c/5802:libudev:1:/dev/bus/usb/004/003 (lun: 0)
nov 05 11:56:37 soldur pcscd[4674]: 00065020 winscard.c:1658:SCardTransmit() UnrefReader() count was: 2
nov 05 11:56:37 soldur pcscd[4674]: 00000032 winscard_svc.c:656:ContextThread() TRANSMIT rv=0x0 for client 14
nov 05 11:56:37 soldur pcscd[4674]: 00000182 winscard_svc.c:356:ContextThread() Received command: TRANSMIT from client 14
nov 05 11:56:37 soldur pcscd[4674]: 00000025 readerfactory.c:798:RFReaderInfoById() RefReader() count was: 1
nov 05 11:56:37 soldur pcscd[4674]: 00000008 winscard.c:1613:SCardTransmit() Send Protocol: T=1
nov 05 11:56:37 soldur pcscd[4674]: 00000007 ifdhandler.c:1283:IFDHTransmitToICC() usb:0a5c/5802:libudev:1:/dev/bus/usb/004/003 (lun: 0)
nov 05 11:56:37 soldur pcscd[4674]: 00064471 winscard.c:1658:SCardTransmit() UnrefReader() count was: 2
nov 05 11:56:37 soldur pcscd[4674]: 00000026 winscard_svc.c:656:ContextThread() TRANSMIT rv=0x0 for client 14
nov 05 11:56:37 soldur pcscd[4674]: 00000153 winscard_svc.c:356:ContextThread() Received command: TRANSMIT from client 14
nov 05 11:56:37 soldur pcscd[4674]: 00000018 readerfactory.c:798:RFReaderInfoById() RefReader() count was: 1
nov 05 11:56:37 soldur pcscd[4674]: 00000005 winscard.c:1613:SCardTransmit() Send Protocol: T=1
nov 05 11:56:37 soldur pcscd[4674]: 00000005 ifdhandler.c:1283:IFDHTransmitToICC() usb:0a5c/5802:libudev:1:/dev/bus/usb/004/003 (lun: 0)
nov 05 11:56:37 soldur pcscd[4674]: 00064477 winscard.c:1658:SCardTransmit() UnrefReader() count was: 2
nov 05 11:56:37 soldur pcscd[4674]: 00000027 winscard_svc.c:656:ContextThread() TRANSMIT rv=0x0 for client 14
nov 05 11:56:37 soldur pcscd[4674]: 00000195 winscard_svc.c:356:ContextThread() Received command: TRANSMIT from client 14
nov 05 11:56:37 soldur pcscd[4674]: 00000022 readerfactory.c:798:RFReaderInfoById() RefReader() count was: 1
nov 05 11:56:37 soldur pcscd[4674]: 00000007 winscard.c:1613:SCardTransmit() Send Protocol: T=1
nov 05 11:56:37 soldur pcscd[4674]: 00000005 ifdhandler.c:1283:IFDHTransmitToICC() usb:0a5c/5802:libudev:1:/dev/bus/usb/004/003 (lun: 0)
nov 05 11:56:37 soldur pcscd[4674]: 00024245 winscard.c:1658:SCardTransmit() UnrefReader() count was: 2
nov 05 11:56:37 soldur pcscd[4674]: 00000034 winscard_svc.c:656:ContextThread() TRANSMIT rv=0x0 for client 14
nov 05 11:56:37 soldur pcscd[4674]: 00000158 winscard_svc.c:356:ContextThread() Received command: TRANSMIT from client 14
nov 05 11:56:37 soldur pcscd[4674]: 00000024 readerfactory.c:798:RFReaderInfoById() RefReader() count was: 1
nov 05 11:56:37 soldur pcscd[4674]: 00000007 winscard.c:1613:SCardTransmit() Send Protocol: T=1
nov 05 11:56:37 soldur pcscd[4674]: 00000006 ifdhandler.c:1283:IFDHTransmitToICC() usb:0a5c/5802:libudev:1:/dev/bus/usb/004/003 (lun: 0)
nov 05 11:56:37 soldur pcscd[4674]: 00015497 winscard.c:1658:SCardTransmit() UnrefReader() count was: 2
nov 05 11:56:37 soldur pcscd[4674]: 00000029 winscard_svc.c:656:ContextThread() TRANSMIT rv=0x0 for client 14
nov 05 11:56:37 soldur pcscd[4674]: 00000151 winscard_svc.c:356:ContextThread() Received command: TRANSMIT from client 14
nov 05 11:56:37 soldur pcscd[4674]: 00000023 readerfactory.c:798:RFReaderInfoById() RefReader() count was: 1
nov 05 11:56:37 soldur pcscd[4674]: 00000009 winscard.c:1613:SCardTransmit() Send Protocol: T=1
nov 05 11:56:37 soldur pcscd[4674]: 00000007 ifdhandler.c:1283:IFDHTransmitToICC() usb:0a5c/5802:libudev:1:/dev/bus/usb/004/003 (lun: 0)
nov 05 11:56:38 soldur pcscd[4674]: 00066142 winscard.c:1658:SCardTransmit() UnrefReader() count was: 2
nov 05 11:56:38 soldur pcscd[4674]: 00000035 winscard_svc.c:656:ContextThread() TRANSMIT rv=0x0 for client 14
nov 05 11:56:38 soldur pcscd[4674]: 00000153 winscard_svc.c:356:ContextThread() Received command: TRANSMIT from client 14
nov 05 11:56:38 soldur pcscd[4674]: 00000036 readerfactory.c:798:RFReaderInfoById() RefReader() count was: 1
nov 05 11:56:38 soldur pcscd[4674]: 00000013 winscard.c:1613:SCardTransmit() Send Protocol: T=1
nov 05 11:56:38 soldur pcscd[4674]: 00000012 ifdhandler.c:1283:IFDHTransmitToICC() usb:0a5c/5802:libudev:1:/dev/bus/usb/004/003 (lun: 0)
nov 05 11:56:38 soldur pcscd[4674]: 00014020 winscard.c:1658:SCardTransmit() UnrefReader() count was: 2
nov 05 11:56:38 soldur pcscd[4674]: 00000037 winscard_svc.c:656:ContextThread() TRANSMIT rv=0x0 for client 14
nov 05 11:56:38 soldur pcscd[4674]: 00000116 winscard_svc.c:356:ContextThread() Received command: TRANSMIT from client 14
nov 05 11:56:38 soldur pcscd[4674]: 00000021 readerfactory.c:798:RFReaderInfoById() RefReader() count was: 1
nov 05 11:56:38 soldur pcscd[4674]: 00000006 winscard.c:1613:SCardTransmit() Send Protocol: T=1
nov 05 11:56:38 soldur pcscd[4674]: 00000005 ifdhandler.c:1283:IFDHTransmitToICC() usb:0a5c/5802:libudev:1:/dev/bus/usb/004/003 (lun: 0)
nov 05 11:56:38 soldur pcscd[4674]: 00010278 winscard.c:1658:SCardTransmit() UnrefReader() count was: 2
nov 05 11:56:38 soldur pcscd[4674]: 00000039 winscard_svc.c:656:ContextThread() TRANSMIT rv=0x0 for client 14
nov 05 11:56:38 soldur pcscd[4674]: 00000177 winscard_svc.c:356:ContextThread() Received command: TRANSMIT from client 14
nov 05 11:56:38 soldur pcscd[4674]: 00000037 readerfactory.c:798:RFReaderInfoById() RefReader() count was: 1
nov 05 11:56:38 soldur pcscd[4674]: 00000012 winscard.c:1613:SCardTransmit() Send Protocol: T=1
nov 05 11:56:38 soldur pcscd[4674]: 00000010 ifdhandler.c:1283:IFDHTransmitToICC() usb:0a5c/5802:libudev:1:/dev/bus/usb/004/003 (lun: 0)
nov 05 11:56:38 soldur pcscd[4674]: 00010041 winscard.c:1658:SCardTransmit() UnrefReader() count was: 2
nov 05 11:56:38 soldur pcscd[4674]: 00000035 winscard_svc.c:656:ContextThread() TRANSMIT rv=0x0 for client 14
nov 05 11:56:38 soldur pcscd[4674]: 00000170 winscard_svc.c:356:ContextThread() Received command: TRANSMIT from client 14
nov 05 11:56:38 soldur pcscd[4674]: 00000049 readerfactory.c:798:RFReaderInfoById() RefReader() count was: 1
nov 05 11:56:38 soldur pcscd[4674]: 00000014 winscard.c:1613:SCardTransmit() Send Protocol: T=1
nov 05 11:56:38 soldur pcscd[4674]: 00000011 ifdhandler.c:1283:IFDHTransmitToICC() usb:0a5c/5802:libudev:1:/dev/bus/usb/004/003 (lun: 0)
nov 05 11:56:38 soldur pcscd[4674]: 00008375 winscard.c:1658:SCardTransmit() UnrefReader() count was: 2
nov 05 11:56:38 soldur pcscd[4674]: 00000036 winscard_svc.c:656:ContextThread() TRANSMIT rv=0x0 for client 14
nov 05 11:56:38 soldur pcscd[4674]: 00042378 winscard_svc.c:356:ContextThread() Received command: DISCONNECT from client 14
nov 05 11:56:38 soldur pcscd[4674]: 00000020 readerfactory.c:798:RFReaderInfoById() RefReader() count was: 1
nov 05 11:56:38 soldur pcscd[4674]: 00000005 winscard.c:876:SCardDisconnect() Active Contexts: -1
nov 05 11:56:38 soldur pcscd[4674]: 00000003 winscard.c:877:SCardDisconnect() dwDisposition: 0
nov 05 11:56:38 soldur pcscd[4674]: 00000004 winscard.c:1042:SCardDisconnect() powerState: POWER_STATE_GRACE_PERIOD
nov 05 11:56:38 soldur pcscd[4674]: 00000005 ifdhandler.c:375:IFDHGetCapabilities() tag: 0xFB2, usb:0a5c/5802:libudev:1:/dev/bus/usb/004/003 (lun: 0)
nov 05 11:56:38 soldur pcscd[4674]: 00000004 winscard.c:1056:SCardDisconnect() Stopping polling thread
nov 05 11:56:38 soldur pcscd[4674]: 00000003 ifdhandler.c:340:IFDHStopPolling() usb:0a5c/5802:libudev:1:/dev/bus/usb/004/003 (lun: 0)
nov 05 11:56:38 soldur pcscd[4674]: 00002201 winscard.c:1069:SCardDisconnect() UnrefReader() count was: 2
nov 05 11:56:38 soldur pcscd[4674]: 00000022 winscard_svc.c:538:ContextThread() DISCONNECT rv=0x0 for client 14
nov 05 11:56:38 soldur pcscd[4674]: 00000063 winscard_svc.c:356:ContextThread() Received command: RELEASE_CONTEXT from client 14
nov 05 11:56:38 soldur pcscd[4674]: 00000008 winscard.c:230:SCardReleaseContext() Releasing Context: 0x2A141D69
nov 05 11:56:38 soldur pcscd[4674]: 00000004 winscard_svc.c:464:ContextThread() RELEASE_CONTEXT rv=0x0 for client 14
nov 05 11:56:38 soldur pcscd[4674]: 00000089 winscard_svc.c:348:ContextThread() Client die: 14
nov 05 11:56:38 soldur pcscd[4674]: 00000019 winscard_svc.c:981:MSGCleanupClient() Thread is stopping: dwClientID=14, threadContext @0x12a2330
nov 05 11:56:38 soldur pcscd[4674]: 00000006 winscard_svc.c:987:MSGCleanupClient() Freeing SCONTEXT @0x12a2330
nov 05 11:56:38 soldur pcscd[4674]: 00000007 winscard_svc.c:1002:MSGCleanupClient() Starting suicide alarm in 60 seconds
nov 05 11:56:38 soldur pcscd[4674]: 00399879 eventhandler.c:493:EHStatusHandlerThread() powerState: POWER_STATE_POWERED

Bug#767862: pcscd: Socket activation not working on first try

Reply via email to