[Pcsclite-muscle] Not receiving card removed event

Sam Van Den Berge sam.van.den.berge at telenet.be
Fri Sep 21 01:45:49 PDT 2018


Hello,

I'm having an issue with the correct detection of a card removed event in
pcscd v1.8.23. In my test case I use a card that is not a smart card.
Obviously reading that card fails because it can't be powered on but afterwards
the card removed event is not correctly propagated to my application.

My application will go to the next state when the card is actually removed so
to do this I first check if a card is currently present. If no card is present,
I continue to the next state. If a card is present, I wait infinitely until the
card is removed with a call to SCardGetStatusChange.

Now, if the card is removed somewhere between checking if a card is present and
waiting until the card is removed, the call to wait until the card is removed
(SCardGetStatusChange) will never return.

I've compiled pcsc with DO_TRACE and I attached the application log and pcscd
log here. My comments are surrounded with ===. 

In the log you'll see that there are 2 pcsc contexts. I think context 18 can be
ignored because it is context 17 that needs to receive the card remove event.

The above issue doesn't happen always but it's not that hard to reproduce it
with an invalid smart card. I haven't been able to reproduce this with a valid
smart card though. So not sure if it is related but it looks like the issue
only happens with a muted card (SCARD_STATE_MUTE).

Kr,
Sam.

===============================================================================
============================= application log =================================
===============================================================================

< [40031BC0] SCardEstablishContext 2, (nil), (nil)
> [40031BC0] SCardEstablishContext 848085317
< [40031BC0] SCardListReaders 848085317
> [40031BC0] SCardListReaders 193
< [40031BC0] SCardListReaders 848085317
> [40031BC0] SCardListReaders 193
PC/SC lib version: 1.8.23
Reader: OMNIKEY CardMan (076B:5341) 5341 (OKCM0030902182346400952477638587) 00 00
Reader: OMNIKEY CardMan (076B:5341) 5341 (OKCM0030902182346400952477638587) 00 01
Reader: Cherry SmartTerminal XX44 (046A:002D) 01 00
Number readers: 3
Selected Reader: Cherry SmartTerminal XX44 (046A:002D) 01 00
Waiting for reader to be enabled
Enable reader
< [40031BC0] SCardGetStatusChange 848085317 -1 1
< [40031BC0] SCardGetStatusChange [0] Cherry SmartTerminal XX44 (046A:002D) 01 00 0 0
> [40031BC0] SCardGetStatusChange [0] Cherry SmartTerminal XX44 (046A:002D) 01 00 0 10222
isCardInserted status = 0, state=10222
Card is inserted
Reading eID...
< [40031BC0] SCardEstablishContext 0, (nil), (nil)
> [40031BC0] SCardEstablishContext 1033786989
< [40031BC0] SCardListReaders 1033786989
> [40031BC0] SCardListReaders 193
< [40031BC0] SCardGetStatusChange 1033786989 0 1
< [40031BC0] SCardGetStatusChange [0] OMNIKEY CardMan (076B:5341) 5341 (OKCM0030902182346400952477638587) 00 00 0 0
> [40031BC0] SCardGetStatusChange [0] OMNIKEY CardMan (076B:5341) 5341 (OKCM0030902182346400952477638587) 00 00 0 12
< [40031BC0] SCardGetStatusChange 1033786989 0 1
< [40031BC0] SCardGetStatusChange [0] OMNIKEY CardMan (076B:5341) 5341 (OKCM0030902182346400952477638587) 00 01 0 0
> [40031BC0] SCardGetStatusChange [0] OMNIKEY CardMan (076B:5341) 5341 (OKCM0030902182346400952477638587) 00 01 0 12
< [40031BC0] SCardGetStatusChange 1033786989 0 1
< [40031BC0] SCardGetStatusChange [0] Cherry SmartTerminal XX44 (046A:002D) 01 00 0 0
> [40031BC0] SCardGetStatusChange [0] Cherry SmartTerminal XX44 (046A:002D) 01 00 0 10222
< [40031BC0] SCardConnect 1033786989 Cherry SmartTerminal XX44 (046A:002D) 01 00 2 3
> [40031BC0] SCardConnect 0
< [40031BC0] SCardGetStatusChange 1033786989 0 1
< [40031BC0] SCardGetStatusChange [0] Cherry SmartTerminal XX44 (046A:002D) 01 00 0 0
> [40031BC0] SCardGetStatusChange [0] Cherry SmartTerminal XX44 (046A:002D) 01 00 0 10222
< [40031BC0] SCardConnect 1033786989 Cherry SmartTerminal XX44 (046A:002D) 01 00 2 3
> [40031BC0] SCardConnect 0
error 0x00000032 Beidsdk_GetObjectValue
{
"eid":{
"error": "An error occured while reading the EID"}
}
< [40031BC0] SCardReleaseContext 1033786989
> [40031BC0] SCardReleaseContext
< [40031BC0] SCardGetStatusChange 848085317 -1 1
< [40031BC0] SCardGetStatusChange [0] Cherry SmartTerminal XX44 (046A:002D) 01 00 0 10222
> [40031BC0] SCardGetStatusChange [0] Cherry SmartTerminal XX44 (046A:002D) 01 00 0 10222
isCardInserted status = 0, state=10222
Card is inserted
waiting for eID to be removed
waitForCardRemoved state=10222
< [40031BC0] SCardGetStatusChange 848085317 -1 1
< [40031BC0] SCardGetStatusChange [0] Cherry SmartTerminal XX44 (046A:002D) 01 00 10222 10222


=======================================================================
= After 30 seconds I cancel the SCardGetStatusChange call with a call =
= to SCardCancel from another thread                                  =
=======================================================================


Disable reader
< [4094F400] SCardCancel 848085317
> [40031BC0] SCardGetStatusChange [0] Cherry SmartTerminal XX44 (046A:002D) 01 00 10222 10220 


==========================================================================================
= Even after the cancel, the state is still 220 (SCARD_STATE_MUTE | SCARD_STATE_PRESENT) =
= but clearly the pcscd daemon already noticed the card removed                          =
==========================================================================================


waitForCardRemoved rv = 80100002
waitForCardRemoved state = 10220
Operation cancelled
Waiting for reader to be enabled
> [4094F400] SCardCancel


===============================================================================
================================ pcscd log ====================================
===============================================================================

      Log starts at the point where the invalid smart card is isnerted

00000036 eventhandler.c:421:EHStatusHandlerThread() Card inserted into Cherry SmartTerminal XX44 (046A:002D) 01 00
00000018 eventhandler.c:437:EHStatusHandlerThread() Error powering up card.
01475478 winscard_svc.c:362:ContextThread() Received command: CMD_GET_READERS_STATE from client 17
00802989 winscard_msg_srv.c:255:ProcessEventsServer() Common channel packet arrival
00000056 winscard_msg_srv.c:267:ProcessEventsServer() ProcessCommonChannelRequest detects: 18
00000025 pcscdaemon.c:133:SVCServiceRunLoop() A new context thread creation is requested: 18
00000256 winscard_svc.c:340:ContextThread() Authorized PC/SC client
00000052 winscard_svc.c:344:ContextThread() Thread is started: dwClientID=18, threadContext @0x2bfc8
00000060 winscard_svc.c:362:ContextThread() Received command: CMD_VERSION from client 18
00000054 winscard_svc.c:374:ContextThread() Client is protocol version 4:3
00000020 winscard_svc.c:394:ContextThread() CMD_VERSION rv=0x0 for client 18
00000273 winscard_svc.c:362:ContextThread() Received command: ESTABLISH_CONTEXT from client 18
00000070 winscard.c:215:SCardEstablishContext() Establishing Context: 0x3D9E566D
00000029 winscard_svc.c:458:ContextThread() ESTABLISH_CONTEXT rv=0x0 for client 18
00001115 winscard_svc.c:362:ContextThread() Received command: CMD_GET_READERS_STATE from client 18
00000602 winscard_svc.c:362:ContextThread() Received command: CMD_GET_READERS_STATE from client 18
00000325 winscard_svc.c:362:ContextThread() Received command: CMD_GET_READERS_STATE from client 18
00000367 winscard_svc.c:362:ContextThread() Received command: CMD_GET_READERS_STATE from client 18
00800684 winscard_svc.c:362:ContextThread() Received command: CONNECT from client 18
00000109 winscard_svc.c:496:ContextThread() Authorized client for 'Cherry SmartTerminal XX44 (046A:002D) 01 00'
00000034 winscard.c:259:SCardConnect() Attempting Connect to Cherry SmartTerminal XX44 (046A:002D) 01 00 using protocol: 3
00000030 readerfactory.c:821:RFReaderInfo() RefReader() count was: 1
00111683 winscard.c:339:SCardConnect() Error powering up card: -2146435050 0x80100016
00000038 winscard.c:344:SCardConnect() Card Not Powered
00000022 winscard.c:518:SCardConnect() UnrefReader() count was: 2
00000021 winscard_svc.c:510:ContextThread() CONNECT rv=0x80100067 for client 18
00000646 winscard_svc.c:362:ContextThread() Received command: CMD_GET_READERS_STATE from client 18
00800538 winscard_svc.c:362:ContextThread() Received command: CONNECT from client 18
00000099 winscard_svc.c:496:ContextThread() Authorized client for 'Cherry SmartTerminal XX44 (046A:002D) 01 00'
00000037 winscard.c:259:SCardConnect() Attempting Connect to Cherry SmartTerminal XX44 (046A:002D) 01 00 using protocol: 3
00000020 readerfactory.c:821:RFReaderInfo() RefReader() count was: 1
00111811 winscard.c:339:SCardConnect() Error powering up card: -2146435050 0x80100016
00000051 winscard.c:344:SCardConnect() Card Not Powered
00000040 winscard.c:518:SCardConnect() UnrefReader() count was: 2
00000030 winscard_svc.c:510:ContextThread() CONNECT rv=0x80100067 for client 18
00000606 winscard_svc.c:362:ContextThread() Received command: RELEASE_CONTEXT from client 18
00000054 winscard.c:229:SCardReleaseContext() Releasing Context: 0x3D9E566D
00000034 winscard_svc.c:473:ContextThread() RELEASE_CONTEXT rv=0x0 for client 18
00000160 winscard_svc.c:354:ContextThread() Client die: 18
00000085 winscard_svc.c:1029:MSGCleanupClient() Thread is stopping: dwClientID=18, threadContext @0x2bfc8
00000022 winscard_svc.c:1035:MSGCleanupClient() Freeing SCONTEXT @0x2bfc8
00000441 winscard_svc.c:362:ContextThread() Received command: CMD_GET_READERS_STATE from client 17
00800542 winscard_svc.c:362:ContextThread() Received command: CMD_GET_READERS_STATE from client 17
00800202 eventhandler.c:356:EHStatusHandlerThread() Card Removed From Cherry SmartTerminal XX44 (046A:002D) 01 00
00000064 winscard_svc.c:362:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 17


==========================================================================
= After 30 seconds I cancel the SCardGetStatusChange call from client 17 =
= with a call to SCardCancel from another thread                         =
==========================================================================


59933772 winscard_msg_srv.c:255:ProcessEventsServer() Common channel packet arrival
00000069 winscard_msg_srv.c:267:ProcessEventsServer() ProcessCommonChannelRequest detects: 18
00000024 pcscdaemon.c:133:SVCServiceRunLoop() A new context thread creation is requested: 18
00000263 winscard_svc.c:340:ContextThread() Authorized PC/SC client
00000054 winscard_svc.c:344:ContextThread() Thread is started: dwClientID=18, threadContext @0x31a88
00000061 winscard_svc.c:362:ContextThread() Received command: CANCEL from client 18
00000063 winscard_svc.c:815:MSGSignalClient() Signal client: 17
00000032 winscard_svc.c:818:MSGSignalClient() SIGNAL rv=0x80100002 for client 17 <<<<<<<<<< rv = SCARD_E_CANCELLED
00000056 winscard_svc.c:612:ContextThread() CANCEL rv=0x0 for client 18
00000800 winscard_svc.c:354:ContextThread() Client die: 18
00000093 winscard_svc.c:1029:MSGCleanupClient() Thread is stopping: dwClientID=18, threadContext @0x31a88
00000030 winscard_svc.c:1035:MSGCleanupClient() Freeing SCONTEXT @0x31a88



More information about the pcsclite-muscle mailing list