C_WaitForSlotEvent not returning.

[larssilven]

Problem Description

C_WaitForSlotEvent is not returning when a card is inserted or removed since commit 2c26b73 to the master branch.

Proposed Resolution

Fix the bug.

Steps to reproduce

Call C_WaitForSlotEvent with the slot ID of a reader without a card.
The function will not return when a card is inserted.

Logs

PKCS#11 spy logs before and after the commit referenced above.
Version before the commit:
0.20.0-215-g7893d286.log
The commited version:
0.20.0-216-g2c26b739.log

[frankmorgner]

Can you reproduce this with pkcs11-tool --test-hotplug?

[larssilven]

I can reproduce it with this tool. But I also found a sequence where card insertion was detected with C_WaitForSlotEvent but then removal was not possible to detect. The trick was to first detect a card using C_GetSlotList and then detect the empty slot also using C_GetSlotList. After this when continuing with C_WaitForSlotEvent the card insertion was detected but later it was not possible to detect removal.

Anyway here is a sequence that is always failing and must work:

1. card removed
2. call "pkcs11-tool --test-hotplug".
3. return pressed. Output: slot 0 empty.
4. x pressed.
5. return pressed. Output: Calling C_WaitForSlotEvent
6. Card inserted.
7. Nothing happens. Not even if card is removed inserted repeatedly.

In the revision before information about the card is printed at step 7.

[Jakuje]

I just tested with current master and it seems to work fine for me. Could you share also complete opensc debug logs of opensc? In your trace, I can see that the C_WaitForSlotEvent is not even called in the second case.

[larssilven]

C_WaitForSlotEvent is called but since it is not returning nothing is printed in the log. I had to stop my application with ctrl-C .
I will repeat the test again and use the current master branch and test with "pkcs11-tool --test-hotplug". The logs I sent before was from my own application. You will also get the opensc log.

[Jakuje]

C_WaitForSlotEvent is called but since it is not returning nothing is printed in the log. I had to stop my application with ctrl-C .

If it would be blocked inside of C_WaitForSlotEvent of OpenSC, it would print at least information that the function was called and parameters.

I will repeat the test again and use the current master branch and test with "pkcs11-tool --test-hotplug". The logs I sent before was from my own application. You will also get the opensc log.

Thanks.

[larssilven]

Here you got the logs for the test described here #2021 (comment) :
master-p11.log
master-opensc.log
It was done for the current master.

The spy is not printing anything until a function returns.

I also did same test with the 2c26b73 commit removed from the master branch with the following result:
fixed-p11.log
fixed-opensc.log
The fixed version version works as it should. I removed and inserted the card before quitting with 'x'.

You can get the my fixed master from my repository https://github.com/larssilven/OpenSC . Just do:
git pull git@github.com:larssilven/OpenSC.git

[Jakuje]

Comparing the debug logs I collected from the test, the main problem is in refresh_attributes(), which calls SCardGetStatusChange(), but the result is SCARD_E_TIMEOUT (no change) instead of detecting the change correctly (as it is in the initial call to SCardGetStatusChange() from pcsc_wait_for_event().

From my understanding, it is because the new code newly stores dwCurrentState in pcsc_wait_for_event() which prevents it from detection of the event in the later function. PCSC trace could confirm that, but I did not get that far yet. Let me check it tomorrow.

[Jakuje]

This patch makes your use case working:

commit 304f87838eac06f5d6c291a92b6492f1b841a8af
Author: Jakub Jelen <jjelen@redhat.com>
Date:   Wed Jun 3 15:41:32 2020 +0200

    Unbreak wait for events

diff --git a/src/libopensc/reader-pcsc.c b/src/libopensc/reader-pcsc.c
index b3da6fc8..808b7553 100644
--- a/src/libopensc/reader-pcsc.c
+++ b/src/libopensc/reader-pcsc.c
@@ -1700,12 +1700,6 @@ static int pcsc_wait_for_event(sc_context_t *ctx, unsigned int event_mask, sc_re
 					r = SC_ERROR_EVENT_TIMEOUT;
 				} else {
 					sc_reader_t *reader = sc_ctx_get_reader_by_name(ctx, rsp->szReader);
-					if (reader) {
-						/* copy the state so we know what to watch out for */
-						struct pcsc_private_data *priv = reader->drv_data;
-						priv->reader_state.dwEventState = state;
-						priv->reader_state.dwCurrentState = prev_state;
-					}
 
 					if ((state & SCARD_STATE_PRESENT) && !(prev_state & SCARD_STATE_PRESENT)) {
 						sc_log(ctx, "card inserted event");

Can you check it works fine for you too?

But neither current master nor with this patch I am able to get reader (yubikey) hotplug working.

[larssilven]

It is working as it should with the patch applied, both with "pkcs11-tool --test-hotplug" and my application. Thank you!
Will you merge your fix into the master branch now?

[Jakuje]

It will probably need some more work to have also the reader hotplug events working (for example for yubikey). This was just the minimal patch "revert" to unbreak card hotplug as it was working before. I am not sure what was the intention of this part of the code. @frankmorgner ? I can probably have a better look into that, but not sure when.

[frankmorgner]

I've created #2051 with the suggested fix. I remember that I've copied the part in question from the existing code without completely retracing its effect. I've additionally verified opensc-notify still works (it was the original reason for rewriting that part back then).

I've also noticed that hotplug events were propagated delayed (if not waiting infinitely). I've fixed that as well in the PR... I'll try to check on Windows once CI finishes.