search

str4d / age-plugin-yubikey

YubiKey plugin for age
Apache License 2.0
598 stars 26 forks source link

UX: interaction with yubikey-agent #136

Open supermarin opened 1 year ago

supermarin commented 1 year ago

From README:

If the current PIN UX proves to be insufficient, a decryption agent will most likely be implemented as a separate age plugin that interacts with [yubikey-agent](https://github.com/FiloSottile/yubikey-agent), enabling YubiKeys to be used simultaneously with age and SSH.

After using yubikey-agent and yubikey-agent-plugin for ~a month exclusively (completely switched ssh, age and pgp keys to yubi+age) I think the UX is not as good as it could be. My workflow consists of frequent ssh, git and age usage and every time I ssh/git, the pin cache gets invalidated. There is one potential downside of interacting with yubikey-agent: it's pinentry logic only supports GUI programs as opposed to age-plugin-yubikey which supports tty. Would prefer if tty was supported for both.

All in all, as much as I appreciate the modular design, think age, yubikey-agent and age-plugin-yubikey should be integrated a bit more seamlessly.

str4d commented 1 year ago

After using yubikey-agent and yubikey-agent-plugin for ~a month exclusively (completely switched ssh, age and pgp keys to yubi+age) I think the UX is not as good as it could be.

To clarify, you mean you were using yubikey-agent and age-plugin-yubikey? Were you using a published release of age-plugin-yubikey or did you install from the current master branch? The latter has significantly improved interoperability with yubikey-agent (and is what that part of the README is written relative to).

(EDIT: I see you're one of the users who commented on https://github.com/str4d/age-plugin-yubikey/issues/115 so I'm guessing you are working from the master branch.)

My workflow consists of frequent ssh, git and age usage and every time I ssh/git, the pin cache gets invalidated.

This is unfortunately unavoidable for age-plugin-yubikey, even after the PIN caching improvements we are making (currently in master, for release in 0.4.0). As I documented in https://github.com/str4d/age-plugin-yubikey/issues/115#issuecomment-1426877356, switching away from the PIV applet forces its PIN cache to be cleared. For your workflow, this will happen frequently:

If you're solely using yubikey-agent for SSH, then my guess is that the PIN cache is only being invalidated when you sign git commits, and not by SSH. If that is not the case (i.e. SSH usage is invalidating your PIN for age decryption), and you're using a YubiKey 5, there might be things we can do to further improve PIN cache preservation.

However, there is nothing I can do about the git / age interaction in age-plugin-yubikey because it is an ephemeral application. The only thing that any app can do in this usage scenario is cache your PIN unencrypted in memory, so that when the YubiKey's internal PIN cache gets cleared, the app can re-enter the PIN automatically. age-plugin-yubikey can't do that because it is ephemeral; an agent could do so, but I personally would not want this to be done (even the YubiKey isn't really "caching the PIN", it's "caching the fact that the PIN was entered").

supermarin commented 1 year ago

To clarify, you mean you were using yubikey-agent and age-plugin-yubikey? Were you using a published release of age-plugin-yubikey or did you install from the current master branch? The latter has significantly improved interoperability with yubikey-agent (and is what that part of the README is written relative to).

master

Signing git commits uses the OpenPGP applet.

FWIW I'm not signing commits with gpg anymore

SSH can use the PIV applet (this is what yubikey-agent does), but it can also use the OpenPGP, FIDO2, or OTP applets depending on how your SSH is set up.

I'm on nixos and pretty sure I've killed gpg and all the other ssh agents except yubikey-agent.

Sometimes the behavior I see is this:

  1. age decrypt [no pin]
  2. age decrypt again within 2-3 seconds [pin requested]

There's no other interactions to the key between the two attempts. Sometimes it just straight requests the pin. It just feels "off" ux wise compared to the gpg workflow I had before.

I haven't had time to debug this in detail and narrow down when/what exactly happens for the pin to clear.

str4d commented 1 year ago

There's not much I can do to figure out improvements without having further details. In particular, I'd need the YubiKey version, and output from decrypting with RUST_LOG=trace environment variable set (after sanitizing to remove sensitive details) across the relevant behaviour (showing first a no-requested-PIN decryption, followed by a PIN-requested decryption).

That still might not be sufficient to figure this out though; we might actually need a full trace of the traffic going to the YubiKey from all sources including other apps. All it takes is one other app on your system to connect to the YubiKey (just to discover that it exists, not even to use it - this was one of the bugs I had to fix in age-plugin-yubikey) and then disconnect by resetting, and the PIN cache gets cleared. If that's the problem, then there's nothing we can do on our side, and you'd have to get that other app updated.

In the meantime, I'm not going to block the 0.4.0 release on this issue, as AFAICT the PIN caching behaviour is working pretty well for most people and most use cases.

supermarin commented 1 year ago

I'll have time this week to dig in and get to the bottom of this. After a lot of usage (and PIN inputs lol), this is what I'm consistently observing:

  1. If yubikey-agent owns the session, I can ssh and git push all day long, key touch required for each one.
  2. The first age-plugin-yubikey decryption requires no PIN, but requires a touch. Even if the last time I've input the PIN was yesterday.
  3. Subsequent age-plugin-yubikey interactions prompt me for PIN.

One thing I'm doing that might be different from the rest is I'm reading the identity off of the key every time (instead of storing it into a file somewhere). This is my decrypt invocation:

age -i <(age-plugin-yubikey --identity --slot 1 2>/dev/null) -d

Tried running age-plugin-yubikey with RUST_LOG=trace but got no extra output. Do I need to compile a dev binary for this?

EDIT: age-plugin-yubikey 0.4.0 from nixpkgs

str4d commented 1 year ago
  1. If yubikey-agent owns the session, I can ssh and git push all day long, key touch required for each one.

To confirm, this is with an identity that has PIN policy "Once" and touch policy "Always"? And behaving as you intend?

One thing I'm doing that might be different from the rest is I'm reading the identity off of the key every time (instead of storing it into a file somewhere).

Okay, that is very different to what I'd been expecting! And this combined with the other parts of your observation gives a hint as to where we should be looking:

  1. The first age-plugin-yubikey decryption requires no PIN, but requires a touch. Even if the last time I've input the PIN was yesterday.

This suggests that age-plugin-yubikey --identity followed by age-plugin-yubikey --age-plugin identity-v1 (the latter being what the age client calls internally) works fine.

  1. Subsequent age-plugin-yubikey interactions prompt me for PIN.

This suggests that age-plugin-yubikey --age-plugin identity-v1 followed by age-plugin-yubikey --identity causes the cache to be reset somewhere (and each subsequent decryption would also have this pattern).

It would be useful to determine whether the cache is being cleared by the decryption, or the identity generation.

Tried running age-plugin-yubikey with RUST_LOG=trace but got no extra output. Do I need to compile a dev binary for this?

You'd need to provide that as an environment variable to age. (IDK if age passes env variables through to plugins though; rage does.)

supermarin commented 1 year ago

:man_facepalming: looking back at my own snippet, turns out RUST_LOG=trace works better if you don't send STDOUT to /dev/null

What you wrote makes sense and seems like --age-plugin-yubikey identity 1 could be the smoking gun.

  If yubikey-agent owns the session, I can ssh and git push all day long, key touch required for each one.

To confirm, this is with an identity that has PIN policy "Once" and touch policy "Always"? And behaving as you intend?

Yep left that here for posterity, but to elaborate fully: that behaviour is expected and set by default by yubikey-agent.

Here's a RUST_LOG=trace enabled log of 2 actions (encrypt and decrypt), both prompted me for PIN. They were run one right after another. Let me know if you need any of the redacted data that's OK to share.

main 130 (24842 ms) $ age -R $AGE_RECIPIENTS_FILE deleteme-age-testing.com                                                                                                                                                                  
[INFO  i18n_embed::requester] Current Locale: [LanguageIdentifier { language: Language(Some("en")), script: None, region: Some(Region("US")), variants: None }]
[DEBUG i18n_embed] Selecting translations for domain "age_plugin_yubikey"
[DEBUG i18n_embed] Searching for available languages, found language file: "en-US/age_plugin_yubikey.ftl"
[DEBUG i18n_embed] Requested Languages: [LanguageIdentifier { language: Language(Some("en")), script: None, region: Some(Region("US")), variants: None }]
[DEBUG i18n_embed] Available Languages: [LanguageIdentifier { language: Language(Some("en")), script: None, region: Some(Region("US")), variants: None }]
[DEBUG i18n_embed] Supported Languages: [LanguageIdentifier { language: Language(Some("en")), script: None, region: Some(Region("US")), variants: None }]
[DEBUG i18n_embed] Attempting to load language file: "en-US/age_plugin_yubikey.ftl"
[DEBUG i18n_embed::fluent] Loaded language file: "en-US/age_plugin_yubikey.ftl" for language: "en-US"
[INFO  yubikey::yubikey] connected to reader: Yubico YubiKey OTP+FIDO+CCID 00 00
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: SelectApplication, p1: 4, p2: 0, data: [...redacted] }
[TRACE yubikey::transaction] >>> [0, 164, 4, 0, 5, 160, 0, 0, 3, 8]
[TRACE yubikey::apdu] <<< Response { status_words: Success, data: [...redacted] }
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetVersion, p1: 0, p2: 0, data: [...redacted] }
[TRACE yubikey::transaction] >>> [0, 253, 0, 0, 0]
[TRACE yubikey::apdu] <<< Response { status_words: Success, data: [...redacted] }
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetSerial, p1: 0, p2: 0, data: [...redacted] }
[TRACE yubikey::transaction] >>> [0, 248, 0, 0, 0]
[TRACE yubikey::apdu] <<< Response { status_words: Success, data: [...redacted] }
[INFO  yubikey::yubikey] connected to reader: Yubico YubiKey OTP+FIDO+CCID 00 00
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: SelectApplication, p1: 4, p2: 0, data: [...redacted] }
[TRACE yubikey::transaction] >>> [0, 164, 4, 0, 5, 160, 0, 0, 3, 8]
[TRACE yubikey::apdu] <<< Response { status_words: Success, data: [...redacted] }
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetVersion, p1: 0, p2: 0, data: [...redacted] }
[TRACE yubikey::transaction] >>> [0, 253, 0, 0, 0]
[TRACE yubikey::apdu] <<< Response { status_words: Success, data: [...redacted] }
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetSerial, p1: 0, p2: 0, data: [...redacted] }
[TRACE yubikey::transaction] >>> [0, 248, 0, 0, 0]
[TRACE yubikey::apdu] <<< Response { status_words: Success, data: [...redacted] }
[INFO  yubikey::yubikey] connected to reader: Yubico YubiKey OTP+FIDO+CCID 00 00
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: SelectApplication, p1: 4, p2: 0, data: [...redacted] }
[TRACE yubikey::transaction] >>> [0, 164, 4, 0, 5, 160, 0, 0, 3, 8]
[TRACE yubikey::apdu] <<< Response { status_words: Success, data: [...redacted] }
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetVersion, p1: 0, p2: 0, data: [...redacted] }
[TRACE yubikey::transaction] >>> [0, 253, 0, 0, 0]
[TRACE yubikey::apdu] <<< Response { status_words: Success, data: [...redacted] }
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetSerial, p1: 0, p2: 0, data: [...redacted] }
[TRACE yubikey::transaction] >>> [0, 248, 0, 0, 0]
[TRACE yubikey::apdu] <<< Response { status_words: Success, data: [...redacted] }
[INFO  yubikey::yubikey] connected to reader: Yubico YubiKey OTP+FIDO+CCID 00 00
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: SelectApplication, p1: 4, p2: 0, data: [...redacted] }
[TRACE yubikey::transaction] >>> [0, 164, 4, 0, 5, 160, 0, 0, 3, 8]
[TRACE yubikey::apdu] <<< Response { status_words: Success, data: [...redacted] }
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetVersion, p1: 0, p2: 0, data: [...redacted] }
[TRACE yubikey::transaction] >>> [0, 253, 0, 0, 0]
[TRACE yubikey::apdu] <<< Response { status_words: Success, data: [...redacted] }
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetSerial, p1: 0, p2: 0, data: [...redacted] }
[TRACE yubikey::transaction] >>> [0, 248, 0, 0, 0]
[TRACE yubikey::apdu] <<< Response { status_words: Success, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted]
[TRACE yubikey::apdu] <<< Response { status_words: BytesRemaining { len: 93 }, data: [...redacted] }
[TRACE yubikey::transaction] The card indicates there is 93 bytes more data for us
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetResponseApdu, p1: 0, p2: 0, data: [...redacted] }
[TRACE yubikey::transaction] >>> [0, 192, 0, 0, 0]
[TRACE yubikey::apdu] <<< Response { status_words: Success, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted]
[TRACE yubikey::apdu] <<< Response { status_words: BytesRemaining { len: 169 }, data: [...redacted] }
[TRACE yubikey::transaction] The card indicates there is 169 bytes more data for us
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetResponseApdu, p1: 0, p2: 0, data: [...redacted] }
[TRACE yubikey::transaction] >>> [0, 192, 0, 0, 0]
[TRACE yubikey::apdu] <<< Response { status_words: Success, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 14]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 15]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 16]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 17]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 18]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 19]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 20]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 21]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 22]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 23]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 24]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 25]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 26]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 27]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 28]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 29]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 30]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 31]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 32]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 1]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 11]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 12]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 15]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
Recipient: age1yubikey1...redacted...
age: waiting on yubikey plugin...
[INFO  i18n_embed::requester] Current Locale: [LanguageIdentifier { language: Language(Some("en")), script: None, region: Some(Region("US")), variants: None }]
[DEBUG i18n_embed] Selecting translations for domain "age_plugin_yubikey"
[DEBUG i18n_embed] Searching for available languages, found language file: "en-US/age_plugin_yubikey.ftl"
[DEBUG i18n_embed] Requested Languages: [LanguageIdentifier { language: Language(Some("en")), script: None, region: Some(Region("US")), variants: None }]
[DEBUG i18n_embed] Available Languages: [LanguageIdentifier { language: Language(Some("en")), script: None, region: Some(Region("US")), variants: None }]
[DEBUG i18n_embed] Supported Languages: [LanguageIdentifier { language: Language(Some("en")), script: None, region: Some(Region("US")), variants: None }]
[DEBUG i18n_embed] Attempting to load language file: "en-US/age_plugin_yubikey.ftl"
[DEBUG i18n_embed::fluent] Loaded language file: "en-US/age_plugin_yubikey.ftl" for language: "en-US"
[INFO  yubikey::yubikey] connected to reader: Yubico YubiKey OTP+FIDO+CCID 00 00
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: SelectApplication, p1: 4, p2: 0, data: [...redacted] }
[TRACE yubikey::transaction] >>> [0, 164, 4, 0, 5, 160, 0, 0, 3, 8]
[TRACE yubikey::apdu] <<< Response { status_words: Success, data: [...redacted] }
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetVersion, p1: 0, p2: 0, data: [...redacted] }
[TRACE yubikey::transaction] >>> [0, 253, 0, 0, 0]
[TRACE yubikey::apdu] <<< Response { status_words: Success, data: [...redacted] }
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetSerial, p1: 0, p2: 0, data: [...redacted] }
[TRACE yubikey::transaction] >>> [0, 248, 0, 0, 0]
[TRACE yubikey::apdu] <<< Response { status_words: Success, data: [...redacted] }
[INFO  yubikey::yubikey] connected to reader: Yubico YubiKey OTP+FIDO+CCID 00 00
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: SelectApplication, p1: 4, p2: 0, data: [...redacted] }
[TRACE yubikey::transaction] >>> [0, 164, 4, 0, 5, 160, 0, 0, 3, 8]
[TRACE yubikey::apdu] <<< Response { status_words: Success, data: [...redacted] }
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetVersion, p1: 0, p2: 0, data: [...redacted] }
[TRACE yubikey::transaction] >>> [0, 253, 0, 0, 0]
[TRACE yubikey::apdu] <<< Response { status_words: Success, data: [...redacted] }
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetSerial, p1: 0, p2: 0, data: [...redacted] }
[TRACE yubikey::transaction] >>> [0, 248, 0, 0, 0]
[TRACE yubikey::apdu] <<< Response { status_words: Success, data: [...redacted] }
[INFO  yubikey::yubikey] connected to reader: Yubico YubiKey OTP+FIDO+CCID 00 00
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: SelectApplication, p1: 4, p2: 0, data: [...redacted] }
[TRACE yubikey::transaction] >>> [0, 164, 4, 0, 5, 160, 0, 0, 3, 8]
[TRACE yubikey::apdu] <<< Response { status_words: Success, data: [...redacted] }
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetVersion, p1: 0, p2: 0, data: [...redacted] }
[TRACE yubikey::transaction] >>> [0, 253, 0, 0, 0]
[TRACE yubikey::apdu] <<< Response { status_words: Success, data: [...redacted] }
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetSerial, p1: 0, p2: 0, data: [...redacted] }
[TRACE yubikey::transaction] >>> [0, 248, 0, 0, 0]
[TRACE yubikey::apdu] <<< Response { status_words: Success, data: [...redacted] }
[INFO  yubikey::yubikey] connected to reader: Yubico YubiKey OTP+FIDO+CCID 00 00
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: SelectApplication, p1: 4, p2: 0, data: [...redacted] }
[TRACE yubikey::transaction] >>> [0, 164, 4, 0, 5, 160, 0, 0, 3, 8]
[TRACE yubikey::apdu] <<< Response { status_words: Success, data: [...redacted] }
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetVersion, p1: 0, p2: 0, data: [...redacted] }
[TRACE yubikey::transaction] >>> [0, 253, 0, 0, 0]
[TRACE yubikey::apdu] <<< Response { status_words: Success, data: [...redacted] }
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetSerial, p1: 0, p2: 0, data: [...redacted] }
[TRACE yubikey::transaction] >>> [0, 248, 0, 0, 0]
[TRACE yubikey::apdu] <<< Response { status_words: Success, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 5]
[TRACE yubikey::apdu] <<< Response { status_words: BytesRemaining { len: 93 }, data: [...redacted] }
[TRACE yubikey::transaction] The card indicates there is 93 bytes more data for us
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetResponseApdu, p1: 0, p2: 0, data: [...redacted] }
[TRACE yubikey::transaction] >>> [0, 192, 0, 0, 0]
[TRACE yubikey::apdu] <<< Response { status_words: Success, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 10]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 11]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 13]
[TRACE yubikey::apdu] <<< Response { status_words: BytesRemaining { len: 169 }, data: [...redacted] }
[TRACE yubikey::transaction] The card indicates there is 169 bytes more data for us
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetResponseApdu, p1: 0, p2: 0, data: [...redacted] }
[TRACE yubikey::transaction] >>> [0, 192, 0, 0, 0]
[TRACE yubikey::apdu] <<< Response { status_words: Success, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 14]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 15]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 16]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 17]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 18]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 19]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 20]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 21]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 22]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 23]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 24]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 25]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 26]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 27]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 28]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 29]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 30]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 31]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 32]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 1]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 11]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 12]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 15]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
Recipient: age1yubikey1...redacted...
age-encrypt called! /dev/shm/pg.IW9ZuRaTCxhQN/MeQcRt--deleteme-age-testing.com-Deleteme-age-testing.age.txt
main $ age -i <(age-plugin-yubikey --identity --slot 1) -d deleteme-age-testing.com
[INFO  i18n_embed::requester] Current Locale: [LanguageIdentifier { language: Language(Some("en")), script: None, region: Some(Region("US")), variants: None }]
[DEBUG i18n_embed] Selecting translations for domain "age_plugin_yubikey"
[DEBUG i18n_embed] Searching for available languages, found language file: "en-US/age_plugin_yubikey.ftl"
[DEBUG i18n_embed] Requested Languages: [LanguageIdentifier { language: Language(Some("en")), script: None, region: Some(Region("US")), variants: None }]
[DEBUG i18n_embed] Available Languages: [LanguageIdentifier { language: Language(Some("en")), script: None, region: Some(Region("US")), variants: None }]
[DEBUG i18n_embed] Supported Languages: [LanguageIdentifier { language: Language(Some("en")), script: None, region: Some(Region("US")), variants: None }]
[DEBUG i18n_embed] Attempting to load language file: "en-US/age_plugin_yubikey.ftl"
[DEBUG i18n_embed::fluent] Loaded language file: "en-US/age_plugin_yubikey.ftl" for language: "en-US"
[INFO  yubikey::yubikey] connected to reader: Yubico YubiKey OTP+FIDO+CCID 00 00
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: SelectApplication, p1: 4, p2: 0, data: [...redacted] }
[TRACE yubikey::transaction] >>> [0, 164, 4, 0, 5, 160, 0, 0, 3, 8]
[TRACE yubikey::apdu] <<< Response { status_words: Success, data: [...redacted] }
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetVersion, p1: 0, p2: 0, data: [...redacted] }
[TRACE yubikey::transaction] >>> [0, 253, 0, 0, 0]
[TRACE yubikey::apdu] <<< Response { status_words: Success, data: [...redacted] }
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetSerial, p1: 0, p2: 0, data: [...redacted] }
[TRACE yubikey::transaction] >>> [0, 248, 0, 0, 0]
[TRACE yubikey::apdu] <<< Response { status_words: Success, data: [...redacted] }
[INFO  yubikey::yubikey] connected to reader: Yubico YubiKey OTP+FIDO+CCID 00 00
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: SelectApplication, p1: 4, p2: 0, data: [...redacted] }
[TRACE yubikey::transaction] >>> [0, 164, 4, 0, 5, 160, 0, 0, 3, 8]
[TRACE yubikey::apdu] <<< Response { status_words: Success, data: [...redacted] }
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetVersion, p1: 0, p2: 0, data: [...redacted] }
[TRACE yubikey::transaction] >>> [0, 253, 0, 0, 0]
[TRACE yubikey::apdu] <<< Response { status_words: Success, data: [...redacted] }
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetSerial, p1: 0, p2: 0, data: [...redacted] }
[TRACE yubikey::transaction] >>> [0, 248, 0, 0, 0]
[TRACE yubikey::apdu] <<< Response { status_words: Success, data: [...redacted] }
[INFO  yubikey::yubikey] connected to reader: Yubico YubiKey OTP+FIDO+CCID 00 00
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: SelectApplication, p1: 4, p2: 0, data: [...redacted] }
[TRACE yubikey::transaction] >>> [0, 164, 4, 0, 5, 160, 0, 0, 3, 8]
[TRACE yubikey::apdu] <<< Response { status_words: Success, data: [...redacted] }
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetVersion, p1: 0, p2: 0, data: [...redacted] }
[TRACE yubikey::transaction] >>> [0, 253, 0, 0, 0]
[TRACE yubikey::apdu] <<< Response { status_words: Success, data: [...redacted] }
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetSerial, p1: 0, p2: 0, data: [...redacted] }
[TRACE yubikey::transaction] >>> [0, 248, 0, 0, 0]
[TRACE yubikey::apdu] <<< Response { status_words: Success, data: [...redacted] }
[INFO  yubikey::yubikey] connected to reader: Yubico YubiKey OTP+FIDO+CCID 00 00
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: SelectApplication, p1: 4, p2: 0, data: [...redacted] }
[TRACE yubikey::transaction] >>> [0, 164, 4, 0, 5, 160, 0, 0, 3, 8]
[TRACE yubikey::apdu] <<< Response { status_words: Success, data: [...redacted] }
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetVersion, p1: 0, p2: 0, data: [...redacted] }
[TRACE yubikey::transaction] >>> [0, 253, 0, 0, 0]
[TRACE yubikey::apdu] <<< Response { status_words: Success, data: [...redacted] }
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetSerial, p1: 0, p2: 0, data: [...redacted] }
[TRACE yubikey::transaction] >>> [0, 248, 0, 0, 0]
[TRACE yubikey::apdu] <<< Response { status_words: Success, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 5]
[TRACE yubikey::apdu] <<< Response { status_words: BytesRemaining { len: 93 }, data: [...redacted] }
[TRACE yubikey::transaction] The card indicates there is 93 bytes more data for us
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetResponseApdu, p1: 0, p2: 0, data: [...redacted] }
[TRACE yubikey::transaction] >>> [0, 192, 0, 0, 0]
[TRACE yubikey::apdu] <<< Response { status_words: Success, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 10]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 11]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 13]
[TRACE yubikey::apdu] <<< Response { status_words: BytesRemaining { len: 169 }, data: [...redacted] }
[TRACE yubikey::transaction] The card indicates there is 169 bytes more data for us
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetResponseApdu, p1: 0, p2: 0, data: [...redacted] }
[TRACE yubikey::transaction] >>> [0, 192, 0, 0, 0]
[TRACE yubikey::apdu] <<< Response { status_words: Success, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 14]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 15]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 16]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 17]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 18]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 19]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 20]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 21]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 22]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 23]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 24]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 25]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 26]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 27]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 28]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 29]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 30]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 31]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 32]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 1]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 11]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 12]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
[TRACE yubikey::transaction] going to send 5 bytes in this go
[TRACE yubikey::apdu] >>> Apdu { cla: 0, ins: GetData, p1: 63, p2: 255, data: [...redacted] }
[TRACE yubikey::transaction] >>> [...redacted prefix, identical to below, 15]
[TRACE yubikey::apdu] <<< Response { status_words: NotFoundError, data: [...redacted] }
Recipient: age1yubikey1...redacted...
plain text output
main $
supermarin commented 1 year ago

@str4d Ping on this one :)

One thing I'm doing that might be different from the rest is I'm reading the identity off of the key every time (instead of storing it into a file somewhere).

Okay, that is very different to what I'd been expecting! And this combined with the other parts of your observation gives a hint as to where we should be looking:

Side question: is there a better way of handling multiple yubikeys at different workstations?

supermarin commented 1 year ago

Update: I've tried caching the key grip to a file, hoping that it will resolve the pin being requested too often. Don't think there's any difference, so the above thesis might be all wrong. Posting the snippet below:

# Contents of `age-decrypt`
# Usage: 
# $ age-decrypt file.age
# $ pbpaste | age-decrypt
ykid=/tmp/yubi-id
test -f $ykid || age-plugin-yubikey --identity --slot 1 > $ykid 2>/dev/null
age -i $ykid -d "$@"

@str4d is there any considerations / plans to revisit the age-plugin-yubikey approach and use a decryption agent?