PIN is (still) requested every time

[bspot]

Environment

• OS: Linux 5.15.80-gentoo-x86_64
• age-plugin-yubikey version: 0.0
• pcsc-lite: 1.9.9
• YubiKey 5 Nano (5.2.6)
• PIN policy is 'Once', touch policy is 'Always'

What were you trying to do

Trying to decrypt multiple times while having to enter the PIN only once, i.e. running

rage --decrypt --identity age-yubikey-identity.txt testdata/encrypted-for-yubikey

multiple times.

What happened

The first time I run the command, I'm asked for my PIN and have to touch the key, as expected.

If I run the command a second time immediately afterwards, the PIN is not required and I just have to touch the key.

However, if I wait only a few seconds before running the command the second time, I will be asked for the PIN again.

I believe that there is a correlation to the output of pcscd -f -d.

After I run the decryption command, the end of the output looks like this:

00000003 [140302233601728] ifdhandler.c:1333:IFDHTransmitToICC() usb:1050/0407:libudev:2:/dev/bus/usb/001/073 (lun: 0)
01820480 [140302233601728] /var/tmp/portage/sys-apps/pcsc-lite-1.9.9/work/pcsc-lite-1.9.9/src/winscard.c:1649:SCardTransmit() UnrefReader() count was: 2
00000037 [140302233601728] /var/tmp/portage/sys-apps/pcsc-lite-1.9.9/work/pcsc-lite-1.9.9/src/winscard_svc.c:694:ContextThread() TRANSMIT for client 13, rv=SCARD_S_SUCCESS
00000257 [140302233601728] /var/tmp/portage/sys-apps/pcsc-lite-1.9.9/work/pcsc-lite-1.9.9/src/winscard_svc.c:361:ContextThread() Received command: END_TRANSACTION from client 13
00000038 [140302233601728] /var/tmp/portage/sys-apps/pcsc-lite-1.9.9/work/pcsc-lite-1.9.9/src/readerfactory.c:866:RFReaderInfoById() RefReader() count was: 1
00000011 [140302233601728] /var/tmp/portage/sys-apps/pcsc-lite-1.9.9/work/pcsc-lite-1.9.9/src/winscard.c:1235:SCardEndTransaction() Status: rv=SCARD_S_SUCCESS
00000009 [140302233601728] /var/tmp/portage/sys-apps/pcsc-lite-1.9.9/work/pcsc-lite-1.9.9/src/winscard.c:1238:SCardEndTransaction() UnrefReader() count was: 2
00000009 [140302233601728] /var/tmp/portage/sys-apps/pcsc-lite-1.9.9/work/pcsc-lite-1.9.9/src/winscard_svc.c:591:ContextThread() END_TRANSACTION for client 13, rv=SCARD_S_SUCCESS
00000201 [140302233601728] /var/tmp/portage/sys-apps/pcsc-lite-1.9.9/work/pcsc-lite-1.9.9/src/winscard_svc.c:361:ContextThread() Received command: DISCONNECT from client 13
00000035 [140302233601728] /var/tmp/portage/sys-apps/pcsc-lite-1.9.9/work/pcsc-lite-1.9.9/src/readerfactory.c:866:RFReaderInfoById() RefReader() count was: 1
00000010 [140302233601728] /var/tmp/portage/sys-apps/pcsc-lite-1.9.9/work/pcsc-lite-1.9.9/src/winscard.c:882:SCardDisconnect() Active Contexts: 1
00000009 [140302233601728] /var/tmp/portage/sys-apps/pcsc-lite-1.9.9/work/pcsc-lite-1.9.9/src/winscard.c:883:SCardDisconnect() dwDisposition: 0
00000011 [140302233601728] /var/tmp/portage/sys-apps/pcsc-lite-1.9.9/work/pcsc-lite-1.9.9/src/winscard.c:1018:SCardDisconnect() powerState: POWER_STATE_GRACE_PERIOD
00000016 [140302233601728] ifdhandler.c:388:IFDHGetCapabilities() tag: 0xFB2, usb:1050/0407:libudev:2:/dev/bus/usb/001/073 (lun: 0)
00000011 [140302233601728] /var/tmp/portage/sys-apps/pcsc-lite-1.9.9/work/pcsc-lite-1.9.9/src/winscard.c:1031:SCardDisconnect() Stopping polling thread
00000012 [140302233601728] ifdhandler.c:353:IFDHStopPolling() usb:1050/0407:libudev:2:/dev/bus/usb/001/073 (lun: 0)
00000189 [140302233601728] /var/tmp/portage/sys-apps/pcsc-lite-1.9.9/work/pcsc-lite-1.9.9/src/winscard.c:1044:SCardDisconnect() UnrefReader() count was: 2
00000030 [140302233601728] /var/tmp/portage/sys-apps/pcsc-lite-1.9.9/work/pcsc-lite-1.9.9/src/winscard_svc.c:560:ContextThread() DISCONNECT for client 13, rv=SCARD_S_SUCCESS
00000217 [140302233601728] /var/tmp/portage/sys-apps/pcsc-lite-1.9.9/work/pcsc-lite-1.9.9/src/winscard_svc.c:361:ContextThread() Received command: RELEASE_CONTEXT from client 13
00000032 [140302233601728] /var/tmp/portage/sys-apps/pcsc-lite-1.9.9/work/pcsc-lite-1.9.9/src/winscard.c:229:SCardReleaseContext() Releasing Context: 0x3A0CF62F
00000012 [140302233601728] /var/tmp/portage/sys-apps/pcsc-lite-1.9.9/work/pcsc-lite-1.9.9/src/winscard_svc.c:480:ContextThread() RELEASE_CONTEXT for client 13, rv=SCARD_S_SUCCESS
00000186 [140302233601728] /var/tmp/portage/sys-apps/pcsc-lite-1.9.9/work/pcsc-lite-1.9.9/src/winscard_svc.c:354:ContextThread() Client die: 13
00000051 [140302233601728] /var/tmp/portage/sys-apps/pcsc-lite-1.9.9/work/pcsc-lite-1.9.9/src/winscard_svc.c:1071:MSGCleanupClient() Thread is stopping: dwClientID=13, threadContext @0x56014addde20
00000013 [140302233601728] /var/tmp/portage/sys-apps/pcsc-lite-1.9.9/work/pcsc-lite-1.9.9/src/winscard_svc.c:1079:MSGCleanupClient() Freeing SCONTEXT @0x56014addde20
00399864 [140302258779840] /var/tmp/portage/sys-apps/pcsc-lite-1.9.9/work/pcsc-lite-1.9.9/src/eventhandler.c:494:EHStatusHandlerThread() powerState: POWER_STATE_POWERED

After about 5 seconds, another two lines appear:

05001449 [140302258779840] ifdhandler.c:1184:IFDHPowerICC() action: PowerDown, usb:1050/0407:libudev:2:/dev/bus/usb/001/073 (lun: 0)
00000423 [140302258779840] /var/tmp/portage/sys-apps/pcsc-lite-1.9.9/work/pcsc-lite-1.9.9/src/eventhandler.c:482:EHStatusHandlerThread() powerState: POWER_STATE_UNPOWERED

I'm rather confident that this marks the time when the Yubikey will require the PIN again to run another decryption.

I don't know what it means that the device is powered down. I have checked that USB autosuspend is turned off for the key. It might be related to https://ludovicrousseau.blogspot.com/2010/10/card-auto-power-on-and-off.html, but I don't see how this would affect only me.

[neurolit]

Hi! I have got a similar problem, on Linux. I didn't check the output of pcscd -f -d yet. Like you, if I wait a few seconds, I will be asked for the PIN again.

• OS: Linux 6.2.12
• pcsclite 1.9.9
• YubiKey 5C Nano (5.2.7)
• PIN policy is 'Once', touch policy is 'Always'

I thought gpg-agent was messing with the Yubikey PIN cache, but after I read your comment, I realized TLP was configured on my laptop. I will check whether USB autosuspend of turned on or off.

[neurolit]

I think I may have the same problem, looking at pcscd logs:

avril 27 09:14:39 pcscd[20099]: 00000008 winscard_svc.c:1079:MSGCleanupClient() Freeing SCONTEXT @0x5595cc0a47e0
avril 27 09:14:39 pcscd[20099]: 00000008 winscard_svc.c:1093:MSGCleanupClient() Starting suicide alarm in 60 seconds
avril 27 09:14:40 pcscd[20099]: 00399855 eventhandler.c:494:EHStatusHandlerThread() powerState: POWER_STATE_POWERED

[waiting 5 seconds, with no decryptions, no log]

avril 27 09:14:45 pcscd[20099]: 05001336 ifdhandler.c:1246:IFDHPowerICC() action: PowerDown, usb:1050/0406:libudev:1:/dev/bus/usb/001/002 (lun: 0)
avril 27 09:14:45 pcscd[20099]: 00000722 eventhandler.c:482:EHStatusHandlerThread() powerState: POWER_STATE_UNPOWERED

[neurolit]

It seems to be the way it works in PCSC-lite: see https://pcsclite.apdu.fr/api/pcscd_8h.html#a470bcb4ab0dad6b913bd9e8772b21715

We could try to recompile it with #define DISABLE_ON_DEMAND_POWER_ON (see https://pcsclite.apdu.fr/api/pcscd_8h_source.html#l00077), but it's a hassle.

Why are we the only ones affected? Maybe most of other users are using MacOS instead of Linux?

[neurolit]

I recompiled pcsc-lite with this patch:

diff --color --unified --recursive --text --color pcsc-lite-1.9.9.orig/src/pcscd.h.in pcsc-lite-1.9.9.new/src/pcscd.h.in
--- pcsc-lite-1.9.9.orig/src/pcscd.h.in 2023-04-27 13:01:58.189410273 +0200
+++ pcsc-lite-1.9.9.new/src/pcscd.h.in  2023-04-27 13:02:55.869596216 +0200
@@ -74,7 +74,7 @@
 #define PCSCLITE_STATUS_EVENT_TIMEOUT 10*60*1000 /* 10 minutes */

 /* Uncomment the next line if you do NOT want to use auto power off */
-/* #define DISABLE_ON_DEMAND_POWER_ON */
+#define DISABLE_ON_DEMAND_POWER_ON

 /* Uncomment the next line if you do not want the card to be powered on
  * when inserted */

and it works. Yubikey is not shutdown after 5 seconds anymore 🎉

Now, pcscd is killed after 60 seconds 🤦‍♂️, if you launch it using systemd: https://ludovicrousseau.blogspot.com/2011/11/pcscd-auto-start-using-systemd.html

It would be soooooo easier if age-plugin-yubikey was using an agent!

[peff]

Why are we the only ones affected? Maybe most of other users are using MacOS instead of Linux?

That's my guess, as well; as far as I can tell, everybody using pcscd (and I think that is the only option on Linux) would hit this. I just opened https://github.com/LudovicRousseau/PCSC/pull/158 which makes it possible to address this at runtime (rather than having to rebuild). Let's see what the maintainer says.

I do think having a separate long-running agent would likewise fix the problem (without changes to pcscd). And maybe could even be more efficient, if it cached the PIN and let the yubikey power down.

[LudovicRousseau]

The solution proposed by @peff will work but is not a correct solution. If you do not want pcscd to auto power off and auto exit then you just have to run a process that creates and maintains an open connection to the reader. This process can be independent from age-plugin-yubikey.

For example in Python using PySCard it could be as simple as:

from smartcard.System import readers
from time import sleep

# use the 1st reader
connection = readers()[0].createConnection()
connection.connect()

while True:
    sleep(10)

[supermarin]

I'm not sure this is the right solution either. If you use both age-plugin-yubikey and yubikey-agent for SSH, keeping a reader alive won't let yubikey-agent connect until you kill the process

[LudovicRousseau]

New version of my Python script. Instead of keeping a permanent connection to the card, the new version connects and disconnects immediately so the card is available for other programs.

The idea is to repeat that every 4 seconds so before the 5 seconds pcscd auto power off timeout.

from smartcard.System import readers
from smartcard.scard import SCARD_LEAVE_CARD
from smartcard.Exceptions import CardConnectionException
from time import sleep

# use the 1st reader
connection = readers()[0].createConnection()

while True:
    try:
        connection.connect(disposition=SCARD_LEAVE_CARD)
        connection.disconnect()
    except CardConnectionException:
        pass
    sleep(4)

[supermarin]

Thanks @LudovicRousseau!

For anyone using nixos, I created a flake that exposes a systemd service running this script above. Tested on x86_64-linux and works ok.

[peff]

I tried the suggested script earlier and found a few corner cases:

• it is picking only the first reader, which may or may not be the one of interest (on my system, there is an internal smartcard reader that I never use). That can be fixed by either connecting to all of them, or scanning for ones with "yubikey" in the name

  • it picks a card at the beginning, so it does not handle cards being plugged in or cards leaving. I tried listening on card-status changes to detect this, but didn't have any luck. However, in the most recent version that @LudovicRousseau posted, we are connecting/disconnecting in each iteration of the loop anyway. So we can likewise just scan the list of available readers.

So I was able to shorten my script down to just this:

#!/usr/bin/perl

use Chipcard::PCSC;

my $ctx = Chipcard::PCSC->new;
while (1) {
  for (grep { /yubikey/i } $ctx->ListReaders) {
    Chipcard::PCSC::Card->new($ctx, $_, $Chipcard::PCSC::SCARD_SHARE_SHARED);
  }
  sleep(4);
}

(there's no real reason to write in perl vs python; it was simply what I turned to when initially when writing my version). It seems to work, though I haven't tested it for more than a few minutes.

I do still find this approach to be pretty hacky compared to just telling pcscd not to power-off, but I guess hacky is in the eye of the beholder.

[permezel]

Curiously, I was fighting this issue all yesterday, and finally arrived at this repo to file a bug report, and instead, I found a fix. Not just a fix, but a flakey fix. How good is that?

I have lots of YubiKeys and I pull them out and plug them in again whenever. So i had a crack at the script. My version. Seems to work, but tomorrow I will test more.

 #!/usr/bin/env python3

import os
import logging

from smartcard.System import readers
from smartcard.scard import SCARD_LEAVE_CARD
from smartcard.Exceptions import CardConnectionException
from time import sleep

LOGFILE='/tmp/pcscd-keep-alive.log'

def logger_init(logf = LOGFILE):
    # see if LOGFILE exists
    try:
        inode = os.stat(LOGFILE)
    except:
        inode = None

    # if it exists, remove it
    if inode is not None:
        try:
            os.unlink(LOGFILE)
        except Exception as err:
            print(f"Unexpected {err=}, {type(err)=}")
            print(f"{LOGFILE}: cannot unlink")
            return None

    try:
        con = logging.StreamHandler()
        fil = logging.FileHandler(LOGFILE)
        fmt = logging.Formatter('%(asctime)s - %(message)s')
        log = logging.getLogger('pcscd-keep-alive.log')

        log.setLevel(logging.DEBUG)
        fil.setLevel(logging.DEBUG)
        con.setLevel(logging.ERROR)

        con.setFormatter(fmt)
        fil.setFormatter(fmt)

        log.addHandler(con)
        log.addHandler(fil)

        return log
    except:
        return None

def debug(msg):
    if logger is not None:
        logger.debug(msg)

def info(msg):
    if logger is not None:
        logger.info(msg)

def warn(msg):
    if logger is not None:
        logger.warning(msg)

logger = logger_init()

info('starting up')

active=set()

while True:
    try:
        rdr = readers()
        cur = set()

        for r in rdr:
            cur.add(r)

        # debug(f"{active=} {cur=}")

        for r in rdr:
            if r not in active:
                active.add(r)
                info(f"{r}: plugged in")

            try:
                conx = r.createConnection()
                try:
                    conx.connect(disposition=SCARD_LEAVE_CARD)
                    conx.disconnect()
                except CardConnectionException as err:
                    warn(f"{r}: createConnection: {err=}")
                except Exception as err:
                    debug(f"{r}: Unexpected {err=}, {type(err)=}")
                except:
                    debug("not reached")

                del conx

            except Exception as err:
                debug(f"{r}: Unexpected {err=}, {type(err)=}")
            except:
                debug("not reached")

        # keep the active set up-to-date
        for r in (active - cur):
            info(f"{r}: removed")
            active.remove(r)

    except Exception as err:
        debug(f"Unexpected {err=}, {type(err)=}")
    except:
        debug("not reached")

    sleep(4)

[supermarin]

I do still find this approach to be pretty hacky compared to just telling pcscd not to power-off, but I guess hacky is in the eye of the beholder.

@peff agreed with you on the approach.

Here's my understanding of all the approaches:

1. The best solution for the problem would be in-memory age agent, with a short lived access to pcscd. This would mitigate both the power consumption issue, and multiple readers issue.
2. Long-lived process is OK for desktop systems, but bad for laptops because of extra power consumption. Has anyone measured the impact of this?
3. The next best solution seems to be a service running one of these pcscd ping scripts with support for multiple readers, that gets killed on battery and runs on A/C power. This would mitigate power consumption on laptops, and would keep living while connected to a charger or desktop systems.

[LudovicRousseau]

From https://github.com/str4d/age-plugin-yubikey#agent-support

Agent support

age-plugin-yubikey does not provide or interact with an agent for decryption. It does however attempt to preserve the PIN cache by not soft-resetting the YubiKey after a decryption or read-only operation, which enables YubiKey identities configured with a PIN policy of once to not prompt for the PIN on every decryption.

If you want to cache the PIN you should do that in age or age-plugin-yubikey.