Stop monitoring reader on some windows system

Question

Stop monitoring reader on some windows system

Closed this issue 9 years ago · 48 comments

Hello,

We have some windows configuration where card events are not received after first card removal. This windows are dev PC with mixed middlewares installation (gemalto, charismathics, personnal, alladin, ...). Maybe it's related, or not. I try to investigate on this.

For now, I see that monitoring stopped when SCARD_STATE_UNAVAILABLE is set. On this PC this event is triggered on card removal, but reader is still connected. In first and very fast analyse I should remove the check on this flag, but I think there is good reason for it (On linux or mac OS maybe ?).

I do some more tests, and come back to you with more informations on our windows stations. (value of other flags and return code).

Thanks,

Answer 1 · 2015-09-21T17:38:59.000Z

Ok, ready for testing ! (for this tests SCARD_UNAVAILABLE was removed from exit condition)

I add following trace on cardreader.cpp, when keep_watching==false
printf("**** WATCHING OUT %s /%i/%08x/%08x/%i/%i/",
card_reader_state.szReader,
reader->m_state,
result & 0xFFFFFFFF,
card_reader_state.dwCurrentState & 0xFFFFFFFF,
card_reader_state.dwCurrentState & SCARD_STATE_UNKNOWN,
card_reader_state.dwCurrentState & SCARD_STATE_UNAVAILABLE);

And return with result on some plateforme, for some scenarii : Card removal, reader removal, ... Mainly on Windows OS and, if possible, Mac OS X.

Answer 2 · 2015-09-22T11:38:30.000Z

Ok, tests done. On windows, first. Tested: WindowsXP/Vista/Seven/10, with omnikey reader or gemalto usb token.
For all, when card reader is removed we have:
WATCHING OUT OMNIKEY CardMan 1021 0 /0/8010002e/0000000b/0/8/
WATCHING OUT OMNIKEY CardMan 1021 0 /0/8010001d/0000000b/0/8/
WATCHING OUT Gemalto USB Key Smart Card Reader 0 /0/8010001d/0000000b/0/8/
(result code 8010001d is on windows 10, others are 8010002e)

So remove the UNAIVALABLE condition could be a solution, but ...
On MacOSX, without this condition, card reader is never removed.

So, we can't remove UNAVAILABLE for all system. Maybe only windows ? What do you think about this ?

Answer 3 · 2015-09-22T15:13:59.000Z

@framillien Thanks a lot for the info on the issue!!! I'm a little busy ATM but I'll try to look at it ASAP

Answer 4 · 2015-09-23T09:43:45.000Z

Hello, taking a further look at code, after some monitoring problems, I have more interrogations ... Always on the same subject: reader removed.

If I look card reader life cycle, I found two differente lifecycle.
On pcsclite.js: card readers list is maintained on list changes (add or remove).
On cardreader.cpp: each reader state is handled on status change.

I think, I have some error case on windows due to desynchronization between this two life cycles (Reader is always present in list (so, never re-created), but some events stop the monitoring thread)

I can think about two evolutions:

Change in JS part: Remove card reader from list, on "_end" event and no more on missing reader in readers list. (this allow to create it back when monitoring thread end)
Change in cpp part: Monitoring thread never end, unless JS part request card reader removal when card reader is missing in readers list (no more flags analyse for monitoring end).

I test this evolutions, tell me if I am wrong on some analyse.

Thanks,

Answer 5 · 2015-09-23T09:53:42.000Z

@framillien I think your analysis is sound. I was thinking in the same lines: the logic handling whether a reader device is connected or not should be handled in the pcsclite.cpp monitor thread. At this moment, only reader connections are monitored. On the other hand, reader disconnections are handled in the reader.cpp monitor thread. This is obviously causing problems. What do you think?

Probably #43 is related.

Answer 6 · 2015-09-23T11:01:02.000Z

@framillien Can you try with the branch https://github.com/santigimeno/node-pcsclite/tree/fix_locks? Disclaimer: it's a work in progress

Answer 7 · 2015-09-23T13:32:41.000Z

Yes, sound goods ! I try with your branch.

Answer 8 · 2015-09-23T14:50:29.000Z

Ok, this branch fix the problem reported here. I keep another problem with reader disconnect on windows 10, but I have not analysed it for now. So, for me it's ok, and I return with more informations on Windows 10.

Answer 9 · 2015-09-23T14:56:25.000Z

@framillien that's great news. I'll try to make a proper fix ASAP as possible. Thanks!

Answer 10 · 2015-09-24T14:41:20.000Z

Come back for windows 10 problem. On windows 10, we got some errors when calling SCardListReaders when a reader is removed ...
It's not a problem for us if we get the 'error' event, allowing us to reload pcsc after a short time. But ... we don't receive 'error' event. Flag 'do_exit' is handled before error event was sent. I propose you a little patch on pcsclite and cardreader to handle events before exit.

Thanks,

Answer 11 · 2016-01-19T09:21:48.000Z

Hi, I'm having this problem on a Windows 7 configuration, node-pcsclite detects card reader but no card events are received, even with the card inserted before running code. In my development PC all works OK.

I have tested @santigimeno fix_locks branch and it solved de problem, all works as expected now.

Any plans on merge that patch on master?

Thanks, for this nice piece of code.

Answer 12 · 2016-01-19T09:43:55.000Z

@Thelmos are you running the latest version: 0.4.7? I thought I had included the relevant fixes from that branch into master, but it seems I didn't. Sorry for that. As I don't have a Windows box to test on, could you help me debug the issue?
If so, could you please add this line:

fprintf(stderr, "HandleReaderStatusChange - m_state: %d, result: %08X, status: %d\n", reader->m_state, ar->result, ar->status);

at https://github.com/santigimeno/node-pcsclite/blob/master/src/cardreader.cpp#L395?

Then rebuild the module, run the code and paste the output?

Thanks

Answer 13 · 2016-01-19T10:41:43.000Z

Yes, version 0.4.7, the last published.

The line you provided fails to compile, ar is not defined, I changed it to:

fprintf(stderr, "HandleReaderStatusChange - m_state: %d, result: %08X, status: %d\n", reader->m_state, async_baton->async_result->result, async_baton->async_result->status);

And this is the output, hope it helps:

C:\GBV\GBV_APILocal>node pcsclite.js
HandleReaderStatusChange - m_state: 0, result: 00000000, status: 0
New reader detected ACS CCID USB Reader 0

Thanks for the fast response.

Answer 14 · 2016-01-19T10:48:27.000Z

Sorry, about that, it was the wrong line, I wanted to say https://github.com/santigimeno/node-pcsclite/blob/master/src/cardreader.cpp#L339. Anyway, I guess it makes no big difference.
BTW are you running the sample code from examples? If not could you run it and paste the output?
Thanks

Answer 15 · 2016-01-19T10:59:18.000Z

Yes, pcsclite.js is the sample script provided in the project description.

Changed fprintf to line 339 and launched again, no output message besides the reader detection:

C:\GBV\GBV_APILocal>node node_modules\pcsclite\examples\example.js
New reader detected ACS CCID USB Reader 0

Answer 16 · 2016-01-19T11:07:51.000Z

Ok, it looks like the thread is locked in this uv_mutex_lock https://github.com/santigimeno/node-pcsclite/blob/master/src/cardreader.cpp#L396. Can you verify that by adding a some log after that line?

Answer 17 · 2016-01-19T11:28:56.000Z

Added logs, it seems that's not the problem:

C:\GBV\GBV_APILocal>node node_modules\pcsclite\examples\example.js
uv_mutex_lock - BEFORE
uv_mutex_lock - AFTER
New reader detected ACS CCID USB Reader 0

Answer 18 · 2016-01-19T11:39:07.000Z

Just added several log lines, no Lock found in HandlerFunction:

C:\GBV\GBV_APILocal>node node_modules\pcsclite\examples\example.js
uv_mutex_lock - BEFORE
uv_mutex_lock - AFTER
async_baton->async_result->do_exit
memcpy - BEFORE
memcpy - AFTER
uv_mutex_unlock - BEFORE
uv_mutex_unlock - AFTER
uv_async_send - BEFORE
uv_async_send - AFTER
New reader detected ACS CCID USB Reader 0

Answer 19 · 2016-01-19T11:43:07.000Z

Thanks for doing that. Can you check the lock in https://github.com/santigimeno/node-pcsclite/blob/master/src/cardreader.cpp#L335. Also the line you added in https://github.com/santigimeno/node-pcsclite/blob/master/src/cardreader.cpp#L339 can you move it up before the lock?

Answer 20 · 2016-01-19T12:11:24.000Z

No mesage from CardReader::HandleReaderStatusChange, in fact I added one fprintf as the first function line (fprintf(stderr, "HandleReaderStatusChange() - START\n");) and it's not showing at output.

Also added some lines to CardReader::HandlerFunction() in case it can help.

C:\GBV\GBV_APILocal>node node_modules\pcsclite\examples\example.js
uv_mutex_lock#L396 - BEFORE
uv_mutex_lock#L396 - AFTER
reader->m_state: 0
card_reader_state.dwEventState: 131090
New reader detected ACS CCID USB Reader 0

Answer 21 · 2016-01-19T14:14:31.000Z

@Thelmos I don't know what's going on, really. I have added some logs here: https://github.com/santigimeno/node-pcsclite/tree/debug, can you use that code and paste the output please? Thanks

Answer 22 · 2016-01-19T14:22:23.000Z

It looks like a lock somewhere, probably in the main thread. It would be great to attach a debugger to the node process to see where the lock is happening. I don't know how to do that on Windows though :(

Answer 23 · 2016-01-19T15:06:54.000Z

Debug version output:

C:\GBV\GBV_APILocal>node node_modules\pcsclite\examples\example.js
PCSCLite::HandlerFunction - PNP: 1
PCSCLite::HandlerFunction - BEFORE SCardGetStatusChange
PCSCLite::HandleReaderStatusChange - m_state: 0, result: 00000000, do_exit: 0
CardReader::HandlerFunction - BEFORE SCardGetStatusChange
CardReader::HandlerFunction - AFTER SCardGetStatusChange result: 00000000, cur:0, new: 131090
CardReader::HandlerFunction - AFTER MUTEX LOCK m_state: 0
CardReader::HandlerFunction - BEFORE SCardGetStatusChange
New reader detected ACS CCID USB Reader 0

Answer 24 · 2016-01-19T15:34:53.000Z

I don't know, for some reason the uv_async_send here https://github.com/santigimeno/node-pcsclite/blob/master/src/cardreader.cpp#L417 is failing to trigger CardReader::HandleReaderStatusChange in the main thread :(. I have added a couple of more logs, maybe we can see something

Answer 25 · 2016-01-19T15:49:25.000Z

What's strange is that fix_locks branch works on that same system !?
Here it's the output:

C:\GBV\GBV_APILocal>node node_modules\pcsclite\examples\example.js
PCSCLite::HandlerFunction - PNP: 1
PCSCLite::HandlerFunction - BEFORE SCardGetStatusChange
PCSCLite::HandleReaderStatusChange - m_state: 0, result: 00000000, do_exit: 0
CardReader::GetStatus - uv_async_init : 0
CardReader::HandlerFunction - BEFORE SCardGetStatusChange
CardReader::HandlerFunction - AFTER SCardGetStatusChange result: 00000000, cur:0, new: 131090
CardReader::HandlerFunction - AFTER MUTEX LOCK m_state: 0
CardReader::HandlerFunction - uv_async_send : 0
CardReader::HandlerFunction - BEFORE SCardGetStatusChange
New reader detected ACS CCID USB Reader 0

Answer 26 · 2016-01-19T15:54:47.000Z

Yes, I know. The code is now a little different though. I'll have to look into it more carefully and see if I understand what's going on. Not being a Windows user myself is a problem, so if you can find a way to attach a debugger and get some backtraces I would really appreciate that. Thanks for your time!

Answer 27 · 2016-01-19T15:57:28.000Z

You could also try version 0.4.4 and see if it works for you. After this version is where all the synchronization fixes were commited

Answer 28 · 2016-01-19T16:13:36.000Z

Yes, tested version 0.4.4, it works fine.

Answer 29 · 2016-01-19T16:19:12.000Z

Good to know! So the suspects are 0bcf3d8 or/and 57a74be.
If you had the time, it would be great if you could test in the first and if it still works in the second. Thanks in advance!!

Answer 30 · 2016-01-19T17:09:44.000Z

Tested both versions, still working ... ¿?

Answer 31 · 2016-01-19T17:12:56.000Z

Really? Thanks a lot for this!! :). One final check if you can. Does 0.4.5 work for u? If it does the problem is in b63f33c

Answer 32 · 2016-01-19T17:35:23.000Z

Version 0.4.5 works too!!!

Answer 33 · 2016-01-19T17:37:44.000Z

Ok so the problem is probably here: https://github.com/santigimeno/node-pcsclite/blob/master/src/pcsclite.cpp#L282. A tight loop because SCardListReaders is always returning SCARD_E_INSUFFICIENT_BUFFER. If you could add a log to confirm that, it would be great. Thanks!!

Answer 34 · 2016-01-19T17:59:17.000Z

Master version: Execution enters else at https://github.com/santigimeno/node-pcsclite/blob/master/src/pcsclite.cpp#L285 (so result == SCARD_S_SUCCESS), then prints all logs we have introduced this morning and finally exits:

C:\GBV\GBV_APILocal>node node_modules\pcsclite\examples\example.js
PCSCLite::get_card_readers - result == SCARD_S_SUCCESS
uv_mutex_lock#L396 - BEFORE
uv_mutex_lock#L396 - AFTER
reader->m_state: 0
card_reader_state.dwEventState: 131090
New reader detected ACS CCID USB Reader 0
C:\GBV\GBV_APILocal>

Just for information: Notice that all failed tests exit to command prompt, execution do not hangs.

Answer 35 · 2016-01-20T07:41:15.000Z

I think I found the problem in https://github.com/santigimeno/node-pcsclite/blob/master/src/pcsclite.cpp#L249 call to SCardListReaders, commenting out all #ifdef SCARD_AUTOALLOCATE section and leaving else code makes all work again!!!


/*  
#ifdef SCARD_AUTOALLOCATE
    readers_name_length = SCARD_AUTOALLOCATE;
    result = SCardListReaders(pcsclite->m_card_context,
                              NULL,
                              (LPTSTR)&readers_name,
                              &readers_name_length);
#else
*/
    /* Find out ReaderNameLength */
    result = SCardListReaders(pcsclite->m_card_context,
                              NULL,
                              NULL,
                              &readers_name_length);
    if (result != SCARD_S_SUCCESS) {
        return result;
    }

    /*
     * Allocate Memory for ReaderName and retrieve all readers in the terminal
     */
    readers_name = new char[readers_name_length];
    result = SCardListReaders(pcsclite->m_card_context,
                              NULL,
                              readers_name,
                              &readers_name_length);
//#endif

Answer 36 · 2016-01-21T16:10:17.000Z

@Thelmos Thanks for the info. Still I don't understand why it's not working. I have updated the debug branch with more logs. Could you run the code from https://github.com/santigimeno/node-pcsclite/blob/master/examples/example.js and paste the output? Thanks

Answer 37 · 2016-01-21T16:20:33.000Z

Here you are:

C:\GBV\GBV_APILocal>node node_modules\pcsclite\examples\example.js
PCSCLite::HandlerFunction - PNP: 1
PCSCLite::get_card_readers: ACS CCID USB Reader 0 (23)
PCSCLite::HandlerFunction - BEFORE SCardGetStatusChange ************************
******************
PCSCLite::HandleReaderStatusChange - m_state: 0, result: 00000000, do_exit: 0
CardReader::GetStatus - uv_async_init : 0
CardReader::HandlerFunction - BEFORE SCardGetStatusChange
CardReader::HandlerFunction - AFTER SCardGetStatusChange result: 00000000, cur:
0, new: 131090
CardReader::HandlerFunction - AFTER MUTEX LOCK m_state: 0
CardReader::HandlerFunction - uv_async_send : 0
CardReader::HandlerFunction - BEFORE SCardGetStatusChange
New reader detected ACS CCID USB Reader 0

C:\GBV\GBV_APILocal>

Answer 38 · 2016-01-21T16:31:39.000Z

Ok, can you make in that code the #ifdef SCARD_AUTOALLOCATE block so that it works and paste the output? Thanks!

Answer 39 · 2016-01-21T16:41:48.000Z

Now example.js works and waits for a card in reader, not exiting to command prompt:

C:\GBV\GBV_APILocal>node node_modules\pcsclite\examples\example.js
PCSCLite::HandlerFunction - PNP: 1
PCSCLite::get_card_readers: ACS CCID USB Reader 0 (23)
PCSCLite::HandlerFunction - BEFORE SCardGetStatusChange ************************
******************
PCSCLite::HandleReaderStatusChange - m_state: 0, result: 00000000, do_exit: 0
CardReader::GetStatus - uv_async_init : 0
CardReader::HandlerFunction - BEFORE SCardGetStatusChange
CardReader::HandlerFunction - AFTER SCardGetStatusChange result: 00000000, cur:
0, new: 131090
CardReader::HandlerFunction - AFTER MUTEX LOCK m_state: 0
CardReader::HandlerFunction - uv_async_send : 0
CardReader::HandlerFunction - BEFORE SCardGetStatusChange
New reader detected ACS CCID USB Reader 0
CardReader::HandleReaderStatusChange - BEFORE LOCK
CardReader::HandleReaderStatusChange - m_state: 0, result: 00000000, status: 131
090, do_exit: 0
Status( ACS CCID USB Reader 0 ): { state: 131090, atr: <Buffer > }
card removed
Disconnected

Answer 40 · 2016-01-21T16:45:10.000Z

Simpler add these lines at the top of pcsclite.cpp

#ifdef SCARD_AUTOALLOCATE
#undef SCARD_AUTOALLOCATE
#endif

Answer 41 · 2016-01-21T16:54:02.000Z

With that patch that skips all #ifdef SCARD_AUTOALLOCATE blocks example.js fails again !!!

C:\GBV\GBV_APILocal>node node_modules\pcsclite\examples\example.js
PCSCLite::HandlerFunction - PNP: 1
PCSCLite::get_card_readers: ACS CCID USB Reader 0 (23)
PCSCLite::HandlerFunction - BEFORE SCardGetStatusChange ************************
******************
PCSCLite::HandleReaderStatusChange - m_state: 0, result: 00000000, do_exit: 0
CardReader::GetStatus - uv_async_init : 0
CardReader::HandlerFunction - BEFORE SCardGetStatusChange
CardReader::HandlerFunction - AFTER SCardGetStatusChange result: 00000000, cur:
0, new: 131090
CardReader::HandlerFunction - AFTER MUTEX LOCK m_state: 0
CardReader::HandlerFunction - uv_async_send : 0
CardReader::HandlerFunction - BEFORE SCardGetStatusChange
New reader detected ACS CCID USB Reader 0

C:\GBV\GBV_APILocal>

Answer 42 · 2016-01-21T16:54:42.000Z

Really??? TBH I don't know what's going on... going back to the case where it does not work... if you start an interval in the example to keep the loop active, does it happen anything different?

Answer 43 · 2016-01-21T17:11:21.000Z

Added interval in https://github.com/santigimeno/node-pcsclite/blob/debug/examples/example.js#L7 , it exits to prompt, tried also defining interval in example.js first line ... same result. It seems thread ends silently for some internal error.

...
pcsc.on('reader', function(reader) {

    var interval = setInterval(function() {
        console.log('Waiting ...');
    }, 2000);

    console.log('New reader detected', reader.name);
...

Same result

C:\GBV\GBV_APILocal>node node_modules\pcsclite\examples\example.js
PCSCLite::HandlerFunction - PNP: 1
PCSCLite::get_card_readers: ACS CCID USB Reader 0 (23)
PCSCLite::HandlerFunction - BEFORE SCardGetStatusChange ************************
******************
PCSCLite::HandleReaderStatusChange - m_state: 0, result: 00000000, do_exit: 0
CardReader::GetStatus - uv_async_init : 0
CardReader::HandlerFunction - BEFORE SCardGetStatusChange
CardReader::HandlerFunction - AFTER SCardGetStatusChange result: 00000000, cur:
0, new: 131090
CardReader::HandlerFunction - AFTER MUTEX LOCK m_state: 0
CardReader::HandlerFunction - uv_async_send : 0
CardReader::HandlerFunction - BEFORE SCardGetStatusChange
New reader detected ACS CCID USB Reader 0

C:\GBV\GBV_APILocal>

Answer 44 · 2016-01-21T17:22:38.000Z

Ok. I have updated the debug branch with a fix related to SCARD_AUTOALLOCATE. I don't know if it will fix the problem though: 1f94013

Answer 45 · 2016-01-21T17:33:58.000Z

That solved the problem!!!

C:\GBV\GBV_APILocal>node node_modules\pcsclite\examples\example.js
PCSCLite::HandlerFunction - PNP: 1
PCSCLite::get_card_readers: ACS CCID USB Reader 0 (23)
PCSCLite::HandlerFunction - BEFORE SCardGetStatusChange ************************
******************
PCSCLite::HandleReaderStatusChange - m_state: 0, result: 00000000, do_exit: 0
CardReader::GetStatus - uv_async_init : 0
CardReader::HandlerFunction - BEFORE SCardGetStatusChange
CardReader::HandlerFunction - AFTER SCardGetStatusChange result: 00000000, cur:
0, new: 131090
CardReader::HandlerFunction - AFTER MUTEX LOCK m_state: 0
CardReader::HandlerFunction - uv_async_send : 0
CardReader::HandlerFunction - BEFORE SCardGetStatusChange
New reader detected ACS CCID USB Reader 0
CardReader::HandleReaderStatusChange - BEFORE LOCK
CardReader::HandleReaderStatusChange - m_state: 0, result: 00000000, status: 131
090, do_exit: 0
Status( ACS CCID USB Reader 0 ): { state: 131090, atr: <Buffer > }
card removed
Disconnected

Answer 46 · 2016-01-21T23:46:17.000Z

This is great news! I'll commit the fixes and make a new release. Thanks for the help !!!

Answer 47 · 2016-01-22T07:01:55.000Z

Glad I could help, thanks for this piece of code.

Un saludo ;)

Answer 48 · 2016-01-22T09:21:15.000Z

Fixed in 0.4.8.

Cheers