Recursion too deep in piv_card_reader_lock_obtained

[jeffallen]

Problem Description

While researching #3138, I found a very long backtrace, over a 1000 frames deep. The recursion loop is:

... etc ...
#1023 0x00007f5d0bea5bd5 in piv_find_discovery (card=card@entry=0x7f5d08147000) at ./src/libopensc/card-piv.c:2757
#1024 0x00007f5d0bea5e18 in piv_card_reader_lock_obtained (card=0x7f5d08147000, was_reset=1) at ./src/libopensc/card-piv.c:3798

#1025 0x00007f5d0be39217 in sc_transmit_apdu (card=card@entry=0x7f5d08147000, apdu=apdu@entry=0x7f5d412fc7f0) at ./src/libopensc/apdu.c:635
#1026 0x00007f5d0be9fdd9 in piv_general_io
    (card=card@entry=0x7f5d08147000, ins=ins@entry=203, p1=p1@entry=63, p2=p2@entry=255, sendbuf=sendbuf@entry=0x7f5d412fc8e8 "\\\001~\v]\177", sendbuflen=3, recvbuf=0x7f5d412fc950 "\307\034\367\v]\177", recvbuflen=<optimized out>) at ./src/libopensc/card-piv.c:565
#1027 0x00007f5d0bea0101 in piv_get_data (card=card@entry=0x7f5d08147000, enumtag=enumtag@entry=10, buf=buf@entry=0x7f5d412fc948, buf_len=buf_len@entry=0x7f5d412fc940) at ./src/libopensc/card-piv.c:954
#1028 0x00007f5d0bea5bd5 in piv_find_discovery (card=card@entry=0x7f5d08147000) at ./src/libopensc/card-piv.c:2757
#1029 0x00007f5d0bea5e18 in piv_card_reader_lock_obtained (card=0x7f5d08147000, was_reset=0) at ./src/libopensc/card-piv.c:3798

#1030 0x00007f5d0be2ed25 in sc_lock (card=0x7f5d08147000) at ./src/libopensc/card.c:509
#1031 sc_lock (card=card@entry=0x7f5d08147000) at ./src/libopensc/card.c:462
#1032 0x00007f5d0be43622 in sc_pkcs15_get_pin_info (p15card=p15card@entry=0x7f5d0a9cb340, pin_obj=<optimized out>) at ./src/libopensc/pkcs15-pin.c:696
#1033 0x00007f5d1755056a in slot_get_logged_in_state (slot=slot@entry=0x7f5d0a979300) at ./src/pkcs11/framework-pkcs15.c:1391
#1034 0x00007f5d17536298 in C_GetSessionInfo (hSession=<optimized out>, pInfo=0x7f5d412fcda0) at ./src/pkcs11/pkcs11-session.c:279

There were 200 instances of piv_card_reader_lock_obtained in my backtrace. I suspect that this recursion consumes all stack space, causing #3138.

The call to piv_card_reader_lock_obtained from sc_lock is legitimate. At frame 1025, the call to sc_transmit_apdu is where the system discovers that the card is no longer present, in line 635:

	if (r == SC_ERROR_CARD_RESET || r == SC_ERROR_READER_REATTACHED) {
		sc_invalidate_cache(card);
		/* give card driver a chance to react on resets */
		if (card->ops->card_reader_lock_obtained)
			card->ops->card_reader_lock_obtained(card, 1);                 // line 635
	}

So it seems that while locking the card, we enter a recursive loop by giving the card a 2nd (and 3rd, and 4th, etc) chance when we get an error talking to it.

There is the nice was_reset argument to pic_card_reader_lock_obtained, which we could use to avoid calling discover again?

Steps to reproduce

Same as #3138: Firefox uses pkcs11 card, sleep, remove card, wake, crash.

[jeffallen]

I put a workaround in like this, and my problem went away:

static int piv_card_reader_lock_obtained(sc_card_t *card, int was_reset)
{
        int r = 0;
        u8 temp[256];
        size_t templen = sizeof(temp);
        piv_private_data_t * priv = PIV_DATA(card); /* may be null */

        // added this to stop the recursion
        if (was_reset) {
                r = SC_ERROR_NO_CARD_SUPPORT;
                goto err;
        }

I don't think it's the right fix, but it's a fix.

[dengert]

This problem maybe in other card drivers, as some also use the reader_lock_obtained feature.

https://github.com/OpenSC/OpenSC/blob/master/src/libopensc/card-piv.c#L6139-L6143 added by
f6b4a2e does have a TODO that this code might be called recursively. Looks like you found a case where this happens.

Although f6b4a2e deals with PIV Secure Messaging from NIST sp800-73-4, the problem may occur without SM.
Did you build OpenSC with --enable-piv_sm?

Can you try this untested fix:

diff --git a/src/libopensc/card-piv.c b/src/libopensc/card-piv.c
index d7e3a4865..a94443a18 100644
--- a/src/libopensc/card-piv.c
+++ b/src/libopensc/card-piv.c
@@ -6153,10 +6153,15 @@ static int piv_card_reader_lock_obtained(sc_card_t *card, int was_reset)
        if (priv == NULL || priv->pstate == PIV_STATE_MATCH) {
                sc_debug(card->ctx, SC_LOG_DEBUG_VERBOSE,
                                priv ? "PIV_STATE_MATCH" : "priv==NULL");
-               r = 0; /* do nothing, piv_match will take care of it */
-               goto err;
+               LOG_FUNC_RETURN(card->ctx, 0);
        }
 
+       if (priv->init_flags | PIV_INIT_IN_READER_LOCK_OBTAINED) {
+               /* recursivly called! */
+               LOG_FUNC_RETURN(card->ctx, 0);
+       }
+
+
        priv->init_flags |= PIV_INIT_IN_READER_LOCK_OBTAINED;
 
        /* make sure our application is active */

[jeffallen]

I build with the stock Debian build (i.e. "apt-get source opensc-pkcs11"), thus: $ ./configure --build=x86_64-linux-gnu --prefix=/usr '--includedir=${prefix}/include' '--mandir=${prefix}/share/man' '--infodir=${prefix}/share/info' --sysconfdir=/etc --localstatedir=/var --disable-option-checking --disable-silent-rules '--libdir=${prefix}/lib/x86_64-linux-gnu' --runstatedir=/run --disable-maintainer-mode --disable-dependency-tracking --enable-pcsc --enable-doc --enable-dnie-ui --enable-notify --enable-readline --enable-sm --enable-zlib --htmldir=/usr/share/doc/opensc/html

[frankmorgner]

could you please post an opensc debug log of one or two cycles of this behavior (level 3 should be enough)?

I think the problem should be more generic. It seems that SCardBeginTransaction returns SCARD_W_RESET_CARD, which causes pcsc_lock to call pcsc_reconnect. After the reconnection, a second call to SCardBeginTransaction should not return SCARD_W_RESET_CARD anymore, which in your case doesn't seem to hold. That problem should then apply to all card driver that are implementing the reader_lock_obtained call back.

[jeffallen]

Where can I read how to get logging working when using the opensc-pkcs11.so plugin in Firefox?

[frankmorgner]

http:https://htmlpreview.github.io/?https://github.com/OpenSC/OpenSC/blob/master/doc/files/files.html#id-1.2.4

If you have the default installation, you only need to uncomment the debugging options from opensc.conf

[jeffallen]

Here is an example of the recursion until crash: opensc-debug.txt

Thanks for your help!

[frankmorgner]

I think the problem is that reader-pcsc.c swallows some errors during transmit which causes the upper layer (card.c) to think that there only happened a reattachment from which one can easily recover. please try the following patch:

diff --git a/src/libopensc/reader-pcsc.c b/src/libopensc/reader-pcsc.c
index 723bcfd01..ef33e3067 100644
--- a/src/libopensc/reader-pcsc.c
+++ b/src/libopensc/reader-pcsc.c
@@ -276,11 +276,15 @@ static int pcsc_internal_transmit(sc_reader_t *reader,
                case SCARD_E_INVALID_HANDLE:
                case SCARD_E_INVALID_VALUE:
                case SCARD_E_READER_UNAVAILABLE:
-                       pcsc_connect(reader);
+                       LOG_TEST_RET(reader->ctx,
+                                       pcsc_connect(reader),
+                                       "Could not connect to card after reattached reader.");
                        /* return failure so that upper layers will be notified */
                        return SC_ERROR_READER_REATTACHED;
                case SCARD_W_RESET_CARD:
-                       pcsc_reconnect(reader, SCARD_LEAVE_CARD);
+                       LOG_TEST_RET(reader->ctx,
+                                       pcsc_reconnect(reader, SCARD_LEAVE_CARD),
+                                       "Could not reconnect to card after reattached reader.");
                        /* return failure so that upper layers will be notified */
                        return SC_ERROR_CARD_RESET;
                default:

[jeffallen]

I'm 99% sure this fixes it for me. The 1% not sure comes from the fact that I have been unable to get a smoking gun A/B test to prove it. The problem just "all of a sudden went away" while working to prove this patch.

[frankmorgner]

Your log showed that your reader, i.e. yubikey, disappeared (SCARD_E_READER_UNAVAILABLE) while being in pcsc_internal_transmit(). Maybe you can add a sleep(10) there and try if unplugging the reader provokes this problem (with and without the fixing patch).

[dengert]

You mentioned the word "suspend" in the original issue. What OS are you using and is this "sleep" or "hibernate". These present special situations as while in sleep or hibernation a card could be removed and replaced or reinserted, which may be the OS taking that into account and causing pcsc to handle it as a special case.

[jeffallen]

This is Debian 12, and it's "sleep", only closing the lid waiting a few seconds, removing the Yubikey and opening the laptop.

I figured out why my before/after were not working (filename confusion left the patch installed while I was trying to reproduce the "before" scenario).

So for me, the patch from @frankmorgner is good to go, it solves this problem.

Thanks for your help.