search

jorgelbg / pinentry-touchid

Custom GPG pinentry program for macOS that allows using Touch ID for fetching the password from the macOS keychain.
Apache License 2.0
521 stars 23 forks source link

help needed: using Yubikey, no touch ID prompt, bad PIN error #20

Open davidxia opened 2 years ago

davidxia commented 2 years ago

Thanks for creating this tool!

environment

I'm using M1 Mac, OS X 12.1, gpg 2.3.4, pinentry-mac 1.1.1.1, pinentry-touchid 0.0.2. My GPG private key is on my Yubikey 5C NFC.

Problem

If I use pinentry-touchid in ~/.gnupg/gpg-agent.conf

pinentry-program /opt/homebrew/opt/pinentry-touchid/bin/pinentry-touchid

and run echo 1234 | gpg -as -, I see

gpg: signing failed: Bad PIN
-----BEGIN PGP MESSAGE-----

gpg: signing failed: Bad PIN

I'm not prompted for a PIN or for touch ID.

What I expect

To be prompted for touch ID, then get encrypted message.

More info

/tmp/pinentry-touchid.log says 2022/02/06 18:19:49 main.go:105: Ready!

gpg-agent.log says

2022-02-06 18:19:49 gpg-agent[95746] starting a new PIN Entry
2022-02-06 18:19:49 gpg-agent[95746] DBG: connection to PIN entry established
2022-02-06 18:19:49 gpg-agent[95746] You may want to update to a newer pinentry
2022-02-06 18:19:50 gpg-agent[95746] DBG: chan_9 -> [ 44 20 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ...(76 byte(s) skipped) ]
2022-02-06 18:19:50 gpg-agent[95746] DBG: chan_9 -> END
2022-02-06 18:19:50 gpg-agent[95746] DBG: chan_9 <- ERR 100663383 Bad PIN <SCD>
2022-02-06 18:19:50 gpg-agent[95746] smartcard signing failed: Bad PIN
2022-02-06 18:19:50 gpg-agent[95746] command 'PKSIGN' failed: Bad PIN <SCD>
2022-02-06 18:19:50 gpg-agent[95746] DBG: chan_8 -> ERR 100663383 Bad PIN <SCD>
2022-02-06 18:19:50 gpg-agent[95746] DBG: chan_8 <- [eof]
2022-02-06 18:19:50 gpg-agent[95746] DBG: chan_9 -> RESTART
2022-02-06 18:19:50 gpg-agent[95746] DBG: chan_9 <- OK

I know my Yubikey and pinentry-mac are working because if I use pinentry-mac in ~/.gnupg/gpg-agent.conf

pinentry-program /opt/homebrew/bin/pinentry-mac

and run echo 1234 | gpg -as -, I'm prompted for my PIN, then the encrypted message shows up in my terminal.

ka2er commented 2 years ago

same issue

jorgelbg commented 2 years ago

Could you enable the debug options for gpg-agent? It seems that it is sending something to pinentry-touchid and but it is just getting an END as a reply? I haven't currently tested this with a Yubikey, but I will give it a try. You can also check the output of $TMPDIR/pinentry-touchid.log to see if anything interesting gets logged.

davidxia commented 2 years ago

@jorgelbg Here's my ~/.gnupg/gpg-agent.conf

enable-ssh-support
default-cache-ttl 600
max-cache-ttl 7200
pinentry-program /opt/homebrew/opt/pinentry-touchid/bin/pinentry-touchid
debug-level guru
log-file /Users/dxia/.gnupg/gpg-agent.log

Here's the output of tail -f /Users/dxia/.gnupg/gpg-agent.log. First I ran gpgconf --kill gpg-agent && gpg-connect-agent reloadagent /bye. Then after the gap below, I ran echo 1234 | gpg -as -. It looks like gpg-agent is trying to ask me to enter the key's secret key, but I am not prompted for it, and the encryption fails.

2022-08-07 21:41:23 gpg-agent[89402] listening on socket '/Users/dxia/.gnupg/S.gpg-agent'
2022-08-07 21:41:23 gpg-agent[89402] listening on socket '/Users/dxia/.gnupg/S.gpg-agent.extra'
2022-08-07 21:41:23 gpg-agent[89402] listening on socket '/Users/dxia/.gnupg/S.gpg-agent.browser'
2022-08-07 21:41:23 gpg-agent[89402] listening on socket '/Users/dxia/.gnupg/S.gpg-agent.ssh'
2022-08-07 21:41:23 gpg-agent[89403] gpg-agent (GnuPG) 2.3.7 started
2022-08-07 21:41:23 gpg-agent[89403] DBG: chan_8 -> OK Pleased to meet you, process 89401
2022-08-07 21:41:23 gpg-agent[89403] DBG: chan_8 <- RESET
2022-08-07 21:41:23 gpg-agent[89403] DBG: chan_8 -> OK
2022-08-07 21:41:23 gpg-agent[89403] DBG: chan_8 <- OPTION ttyname=/dev/ttys005
2022-08-07 21:41:23 gpg-agent[89403] DBG: chan_8 -> OK
2022-08-07 21:41:23 gpg-agent[89403] DBG: chan_8 <- OPTION ttytype=xterm-256color
2022-08-07 21:41:23 gpg-agent[89403] DBG: chan_8 -> OK
2022-08-07 21:41:23 gpg-agent[89403] DBG: chan_8 <- OPTION lc-ctype=en_US.UTF-8
2022-08-07 21:41:23 gpg-agent[89403] DBG: chan_8 -> OK
2022-08-07 21:41:23 gpg-agent[89403] DBG: chan_8 <- OPTION lc-messages=en_US.UTF-8
2022-08-07 21:41:23 gpg-agent[89403] DBG: chan_8 -> OK
2022-08-07 21:41:23 gpg-agent[89403] DBG: chan_8 <- reloadagent
2022-08-07 21:41:23 gpg-agent[89403] SIGHUP received - re-reading configuration and flushing cache
2022-08-07 21:41:23 gpg-agent[89403] DBG: agent_flush_cache
2022-08-07 21:41:23 gpg-agent[89403] reading options from '/Users/dxia/.gnupg/gpg-agent.conf'
2022-08-07 21:41:23 gpg-agent[89403] enabled debug flags: mpi crypto memory cache memstat hashing ipc
2022-08-07 21:41:23 gpg-agent[89403] DBG: chan_8 -> OK
2022-08-07 21:41:23 gpg-agent[89403] DBG: chan_8 <- [eof]
2022-08-07 21:41:27 gpg-agent[89403] DBG: agent_cache_housekeeping

2022-08-07 21:41:31 gpg-agent[89403] DBG: agent_cache_housekeeping
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_8 -> OK Pleased to meet you, process 89415
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_8 <- RESET
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_8 -> OK
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_8 <- OPTION ttyname=/dev/ttys005
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_8 -> OK
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_8 <- OPTION ttytype=xterm-256color
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_8 -> OK
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_8 <- OPTION lc-ctype=en_US.UTF-8
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_8 -> OK
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_8 <- OPTION lc-messages=en_US.UTF-8
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_8 -> OK
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_8 <- GETINFO version
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_8 -> D 2.3.7
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_8 -> OK
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_8 <- OPTION allow-pinentry-notify
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_8 -> OK
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_8 <- OPTION agent-awareness=2.1.0
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_8 -> OK
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_8 <- SCD SERIALNO
2022-08-07 21:41:33 gpg-agent[89403] no running /opt/homebrew/Cellar/gnupg/2.3.7_1/libexec/scdaemon daemon - starting it
2022-08-07 21:41:33 gpg-agent[89403] DBG: agent_flush_cache (pincache only)
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 <- OK GNU Privacy Guard's Smartcard server ready
2022-08-07 21:41:33 gpg-agent[89403] first connection to daemon /opt/homebrew/Cellar/gnupg/2.3.7_1/libexec/scdaemon established
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 -> GETINFO socket_name
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 <- D /Users/dxia/.gnupg/S.scdaemon
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 <- OK
2022-08-07 21:41:33 gpg-agent[89403] DBG: additional connections at '/Users/dxia/.gnupg/S.scdaemon'
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 -> OPTION event-signal=31
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 <- OK
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 -> SERIALNO
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 <- S SERIALNO ***
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_8 -> S SERIALNO ***
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 <- OK
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_8 -> OK
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_8 <- SCD SERIALNO
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 -> SERIALNO
2022-08-07 21:41:33 gpg-agent[89403] SIGUSR2 received - updating card event counter
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 <- S SERIALNO ***
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_8 -> S SERIALNO ***
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 <- OK
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_8 -> OK
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_8 <- SCD GETATTR KEY-FPR
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 -> GETATTR KEY-FPR
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 <- S KEY-FPR 1 ***
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_8 -> S KEY-FPR 1 ***
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 <- S KEY-FPR 2 ***
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_8 -> S KEY-FPR 2 ***
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 <- S KEY-FPR 3 ***
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_8 -> S KEY-FPR 3 ***
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 <- OK
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_8 -> OK
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_8 <- READKEY --card --no-data -- $SIGNKEYID
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 -> GETATTR SERIALNO
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 <- S SERIALNO ***
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 <- OK
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 -> GETATTR $SIGNKEYID
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 <- S $SIGNKEYID OPENPGP.1
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 <- OK
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 -> READKEY -- OPENPGP.1
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 <- [ 44 20 28 31 30 3a 70 75 62 6c 69 63 2d 6b 65 79 ...(546 byte(s) skipped) ]
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 <- OK
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_8 -> OK
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_8 <- READKEY --card --no-data -- $ENCRKEYID
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 -> GETATTR SERIALNO
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 <- S SERIALNO ***
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 <- OK
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 -> GETATTR $ENCRKEYID
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 <- S $ENCRKEYID OPENPGP.2
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 <- OK
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 -> READKEY -- OPENPGP.2
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 <- [ 44 20 28 31 30 3a 70 75 62 6c 69 63 2d 6b 65 79 ...(546 byte(s) skipped) ]
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 <- OK
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_8 -> OK
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_8 <- KEYINFO ***
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 -> KEYINFO --list
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 <- S KEYINFO *** T *** OPENPGP.1 sc
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 <- S KEYINFO *** T *** OPENPGP.2 e
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 <- S KEYINFO *** T *** OPENPGP.3 sa
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 <- OK
2022-08-07 21:41:33 gpg-agent[89403] DBG: agent_get_cache '***'.0 (mode 2) ...
2022-08-07 21:41:33 gpg-agent[89403] DBG: ... miss
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_8 -> S KEYINFO *** T *** OPENPGP.1 - - - - A
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_8 -> OK
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_8 <- RESET
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_8 -> OK
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_8 <- SIGKEY ***
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_8 -> OK
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_8 <- SETKEYDESC Please+enter+the+passphrase+to+unlock+the+OpenPGP+secret+key:%0A%22David+Xia+(personal+PGP+key)+<david@davidxia.com>%22%0A4096-bit+RSA+key,+ID+0x5F38B0A1B60734DF,%0Acreated+2015-05-01+(main+key+ID+0x34469DFBDC90312C).%0A
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_8 -> OK
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_8 <- SETHASH 10 ***
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_8 -> OK
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_8 <- PKSIGN
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 -> SERIALNO --all
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 <- S SERIALNO ***
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 <- OK
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 -> KEYINFO ***
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 <- S KEYINFO *** T *** OPENPGP.1 sc
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 <- OK
2022-08-07 21:41:33 gpg-agent[89403] DBG: encoded hash: *** \
2022-08-07 21:41:33 gpg-agent[89403] DBG:  *** \
2022-08-07 21:41:33 gpg-agent[89403] DBG:  ***
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 -> SETDATA ***
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 <- OK
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 -> PKSIGN --hash=sha512 ***
2022-08-07 21:41:33 gpg-agent[89403] DBG: chan_9 <- [ 49 4e 51 55 49 52 45 20 4e 45 45 44 50 49 4e 20 ...(88 byte(s) skipped) ]
2022-08-07 21:41:33 gpg-agent[89403] starting a new PIN Entry
2022-08-07 21:41:33 gpg-agent[89403] DBG: connection to PIN entry established
2022-08-07 21:41:33 gpg-agent[89403] You may want to update to a newer pinentry
2022-08-07 21:41:34 gpg-agent[89403] DBG: chan_9 -> [ 44 20 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ...(76 byte(s) skipped) ]
2022-08-07 21:41:34 gpg-agent[89403] DBG: chan_9 -> END
2022-08-07 21:41:34 gpg-agent[89403] DBG: chan_9 <- ERR 100663383 Bad PIN <SCD>
2022-08-07 21:41:34 gpg-agent[89403] smartcard signing failed: Bad PIN
2022-08-07 21:41:34 gpg-agent[89403] command 'PKSIGN' failed: Bad PIN <SCD>
2022-08-07 21:41:34 gpg-agent[89403] DBG: chan_8 -> ERR 100663383 Bad PIN <SCD>
2022-08-07 21:41:34 gpg-agent[89403] DBG: chan_8 <- [eof]
2022-08-07 21:41:34 gpg-agent[89403] DBG: chan_9 -> RESTART
2022-08-07 21:41:34 gpg-agent[89403] DBG: chan_9 <- OK
whoo commented 11 months ago

Hi, I've got the same issue. Normal key ... it works (following documentation). Key on Yubikey not.

image

Many thanks.

phoerious commented 8 months ago

I tested it, smart cards seem to be unsupported, you only get this double PIN prompt. Since you have to enter the PIN twice every time, this is objectively worse than the normal pinentry-mac programme.