MacOS: Current master fails to unlock the Yubikey token #1725
Comments
|
Lines 119, 151, 173 all return line 98 line 119: line 137: So something happened between line 98 and 119. Is there some other application running that could have reset the card? Is the Mac PCSC failing to reset the reset? Have to go... |
|
There is a time difference between card.c in sc_lock has: It looks like Can you use a debugger and step through is executed and piv_select_aid returns |
|
What does your step "4 Click Disconnect" actually do? |
|
First, thank you, and happy 4th of July! No, I can't use a debugger - this is not my machine, among other reasons. I'm just getting logs. But I can add another Step "Click 'Disconnect'" means "issue a command to the VPN app to drop secure network connection". The VPN app in question is Pulse Secure, in case it matters. Also, when the tokend is in this state, the user can SSH to the machine in question, and perform operations on the token, e.g., do Maybe not related to this, but I often observe that OpenSC.tokend doesn't detect reliably that the token has been removed. The daemon (tokend) keeps running, as if the card was still inserted (though of course it can't perform any command). The only way to kick it out from this stupor (without reboot) is to re-insert the token, and remove it again in a minute or less. Then tokend usually gets that the token has been removed, and exits. |
|
Is it possible to reproduce the problem with core utils of macOS or OpenSC? Try to avoid concurrency in |
|
So a VPN is involved. |
|
I don't know if it's reproducible - the complaints I'm getting are "screen lock is engaged, and when I come back to unlock it, no matter what PIN I enter, it's rejected with that shaking popup", and "I cannot reconnect my VPN - it prompts me for my PIN, and then says Timeout". I'll try to add the extra logging that @dengert mentioned, and the concurrency-avoiding config change that you showed - and report results. |
|
Both token and tokend are on the client machine, physically. The VPN accesses the token via tokend to PKI-authenticate itself to the remote end (to the server). I don't know PCSC tunneling, but rather doubt it because this VPN app doesn't appear that sofisticated... |
|
Can you get a PCSC debug log? It appears that once it sets the card was reset, it is not cleared. Or it is getting reset multiple times. |
|
Please, again try to confirm if exclusive locking solves the problem. If so, please try #1727 if it solves the problem without exclusive locking. |
|
Thanks, will try as soon as we are back from the July 4 long weekend (until then I've no access to those computers and people who had problems). UpdateDelayed utill Jul 15th - people who have this problem are vacationing. ;-) |
|
The patches work on my machines, but the problem machines still fail. The failure is observed only with Pulse Secure VPN, and only after upgrading macOS to 10.14.4 (persists on 10.14.5). We tried only #1727 - our IT is rather hesitant to do exclusive locking. Perhaps I don't understand fully what "exclusive locking" means, and it's not so bad? We cannot allow one application to usurp the token, unless it's "grab the lock, (quickly) perform an operation, release the lock". |
|
You said: "I don't know if it's reproducible - the complaints I'm getting are "screen lock is engaged, and when I come back to unlock it, no matter what PIN I enter, it's rejected with that shaking popup", and "I cannot reconnect my VPN - it prompts me for my PIN, and then says Timeout". That sounds like a misconfigured VPN or screensaver that has locked the screen or PAM (or whatever MacOS is using). Has the screen saver changed in macOS 0.14.4? Does it know how to use the smart card to unlock the screen? Is the VPN holding the lock on the smartcard in exclusive mode? Can you ssh to the machine while locked and look around? |
IMHO, unlikely. Also, the current "reproducer" is only Pulse Secure VPN app. It looks like screen unlock works smoothly with the new OpenSC (applied #1723 and #1727).
AFAIK, it hasn't.
Yep. And on my machines (thankfully) I experience no problems. It's on machines that belong to others (and so I have limited access to them).
No clue. I personally think that particular VPN app sucks big. But nobody asked for my opinion. ;-)
Don't know. Probably... Although now the biggest issue is that VPN app. Screensaver seems to be behaving fine... Also, the current workaround is removing and re-inserting the token. Does it tell anything about what might be going on? |
|
Looking closer at the debug log and response #1725 (comment) The problem may not have occurred between 98 and 119 as stated in #1725 (comment) A card reset may be what is new in macOS 0.14.4. This could have the triggered an issue in the handling of the reset in Can you try this patch: It is not perfect, but might allow it to get further. If |
What should I expect as a result? Should it start working? |
|
Either. The problem maybe how the reset is being handled. I would expect it would get further and might even work. |
|
Sent the modified binaries to the people involved - will report results. |
|
@mouse07410 I see this difference between your clone and current master in That does not look correct to me. I can not tell from your debug log if this directly related to this issue. But if you or your |
I don't know, as (unfortunately!) I did not record the reason/purpose of that change. Since it does not seem right to you, I'm removing this change - and will test the resulting binary. |
Well, I re-built the library with the lines in question removed - and immediately [re-]discovered why they were there. :-( Without these lines and when I think we tried to address that problem a year ago, and these lines were the best we came up with. Needless to say, I'm open to alternatives. |
|
You said: "screensaver does not prompt for the PIN any more when user tries to unlock the screen." As I said: "card_reader_lock_obtained is meant to be called just after a pcsc lock has been called from sc_lock." At this point if some other process has reset the card. And it is possible some other process may have gotten control prompted the user for pin and reestablished the login state. Problem is some Yubkey do not handle queering of the login state of the card. See in Can I ask your to put the call to |
Possible, but I don't think it's likely. Especially on a machine that's sitting around idle with no user app running that might have any interest in keychains, except for the Screensaver. And the
Updated the code as you suggested, will run and post the log. What's the best way to get logging from tokend? It's trivial with OpenSC commands (e.g., |
|
@dengert please find the log attached. I assume I need to restore the |
|
I don't see any signs of a reset. Do you still do the card reset? If not can you put it back in? Please leave the Note the |
Can't comment - beyond my competence.
What does it mean? Comm failure on PCSC level...? Something unrelated to OpenSC?
Yes, I put that code back in, and the card/system now behaves as expected.
Done.
Yes, it was. Everything seems fine - except that I haven't heard yet from the people with that Pulse Secure issue. Ready for more experiments/tests. |
|
The error code from the transmit is SCARD_W_RESET_CARD, which OpenSC handles only correctly in OpenSC/src/libopensc/reader-pcsc.c Lines 662 to 672 in a7766b3 I think the best way to tackle this problem would be to reconnect and retransmit in Ludovic has a number of bugs related to SCARD_W_RESET_CARD in Apple's implementation... |
|
You could try something like this: diff --git a/src/libopensc/reader-pcsc.c b/src/libopensc/reader-pcsc.c
index a058c71f7..6dbca7721 100644
--- a/src/libopensc/reader-pcsc.c
+++ b/src/libopensc/reader-pcsc.c
@@ -200,6 +200,7 @@ static DWORD opensc_proto_to_pcsc(unsigned int proto)
}
}
+static int pcsc_reconnect(sc_reader_t * reader, DWORD action);
static int pcsc_internal_transmit(sc_reader_t *reader,
const u8 *sendbuf, size_t sendsize,
u8 *recvbuf, size_t *recvsize,
@@ -228,6 +229,13 @@ static int pcsc_internal_transmit(sc_reader_t *reader,
if (!control) {
rv = priv->gpriv->SCardTransmit(card, &sSendPci, sendbuf, dwSendLength,
&sRecvPci, recvbuf, &dwRecvLength);
+ if (rv == SCARD_W_RESET_CARD) {
+ PCSC_TRACE(reader, "SCardTransmit calling pcsc_reconnect", rv);
+ if (SC_SUCCESS == pcsc_reconnect(reader, SCARD_LEAVE_CARD)) {
+ rv = priv->gpriv->SCardTransmit(card, &sSendPci, sendbuf, dwSendLength,
+ &sRecvPci, recvbuf, &dwRecvLength);
+ }
+ }
} else {
if (priv->gpriv->SCardControlOLD != NULL) {
rv = priv->gpriv->SCardControlOLD(card, sendbuf, dwSendLength, |
|
With the proposed change, I do not observe the error getting correctly to Complete log: |
|
Good to finally have found the root cause of this problem! I think we need to generalize the above idea and to take care about possible endless loops. Could you please try the below diff instead? diff --git a/src/libopensc/apdu.c b/src/libopensc/apdu.c
index d32d44040..f4101269e 100644
--- a/src/libopensc/apdu.c
+++ b/src/libopensc/apdu.c
@@ -619,9 +619,18 @@ int sc_transmit_apdu(sc_card_t *card, sc_apdu_t *apdu)
len -= plen;
buf += plen;
}
- } else
+ } else {
/* transmit single APDU */
r = sc_transmit(card, apdu);
+ }
+
+ 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);
+ }
+
/* all done => release lock */
if (sc_unlock(card) != SC_SUCCESS)
sc_log(card->ctx, "sc_unlock failed");
diff --git a/src/libopensc/reader-pcsc.c b/src/libopensc/reader-pcsc.c
index a058c71f7..819ca5266 100644
--- a/src/libopensc/reader-pcsc.c
+++ b/src/libopensc/reader-pcsc.c
@@ -132,6 +132,8 @@ struct pcsc_private_data {
};
static int pcsc_detect_card_presence(sc_reader_t *reader);
+static int pcsc_reconnect(sc_reader_t * reader, DWORD action);
+static int pcsc_connect(sc_reader_t *reader);
static DWORD pcsc_reset_action(const char *str)
{
@@ -244,6 +246,25 @@ static int pcsc_internal_transmit(sc_reader_t *reader,
switch (rv) {
case SCARD_W_REMOVED_CARD:
return SC_ERROR_CARD_REMOVED;
+ case SCARD_E_INVALID_HANDLE:
+ case SCARD_E_READER_UNAVAILABLE:
+ r = pcsc_connect(reader);
+ if (r != SC_SUCCESS) {
+ sc_log(reader->ctx, "pcsc_connect failed (%d)",
+ r);
+ return r;
+ }
+ /* return failure so that upper layers will be notified */
+ return SC_ERROR_READER_REATTACHED;
+ case SCARD_W_RESET_CARD:
+ r = pcsc_reconnect(reader, SCARD_LEAVE_CARD);
+ if (r != SC_SUCCESS) {
+ sc_log(reader->ctx,
+ "pcsc_reconnect failed (%d)", r);
+ return r;
+ }
+ /* return failure so that upper layers will be notified */
+ return SC_ERROR_CARD_RESET;
default:
/* Translate strange errors from card removal to a proper return code */
pcsc_detect_card_presence(reader); |
I really hope so. I still have one machine that belongs to somebody else, whose owner was one of those complaining, and I haven't heard back from him yet. I'll ask again.
Sure.
Re-building as we speak. Will report here as soon as I get something. And thank you for helping with this! |
Should UpdateOf course, it should be I'm still waiting for the confirmation from the "sufferers". ;-) |
|
Sorry, I was a bit too quick. See #1752 for a fix |
|
No problem. Replaced the above patch with #1752, and it seems to work. |
|
Perhaps we can merge #1752 ...? |
|
@mouse07410 you wanted to confirm from your users if the change really fixes the problem |
Problem Description
This started with MacOS Mojave 10.14.5. Native PCSC, current OpenSC master.
I recall something similar a couple of years ago, but not since - until now.
OpenSC fails to unlock the token.
it seems that OpenSC (tokend, specifically?) loses the state of the token, and/or loses the ability to communicate with it.
Proposed Resolution
Don't know yet.
Steps to reproduce
Logs
@dengert do you see anything in the above that could explain what the problem is, and how to fix it, or at least work-around?
The text was updated successfully, but these errors were encountered: