Pinentry-qt does not always become active foreground window (especially when requesting pin for authentication)
Open, NormalPublic

Description

The pinentry-qt dialog appears when a PIN is needed for SSH authentication. However, this does not grab input focus, and appears at the end of the ALT-TAB menu. While the grab option is set in gpg-agent.conf, it doesn't seem to have any effect.

Edit by @aheinecke:
This has been reported and noticed also in other circumstances. We have code in pinentry-qt that tries to pop up in the foreground. On Windows the operating system does not support this properly, so we use hacks. Those hacks do not always work and need more work. Strangely enough the way GTK-2 does it seems to work, but trying to copy that behavior for Qt did not work properly.

Details

Version
3.1.2
a_p3rson created this task.Sep 1 2018, 7:59 AM
aheinecke claimed this task.Sep 4 2018, 8:52 AM
aheinecke added a project: pinentry.
aheinecke triaged this task as Normal priority.
aheinecke added a subscriber: aheinecke.

By grabbing I guess you mean that the cursor / keyboard input is automatically focused on the input field? I also noticed that this sometimes does not work well.

Global grabbing (You can't switch input focus to another window while pinentry is open) is something we purposely do not do anymore.

cepxuo added a subscriber: cepxuo.Sep 17 2018, 7:12 PM

I confirm this bug!

By grabbing I mean that it's not possible to input elsewhere. Same as ssh-askpass does.

werner closed this task as Invalid.Sep 18 2018, 3:34 PM
werner added a subscriber: werner.

Andre explained that we don't do that anymore on purpose. Duck and read the discussion related to this if you are intereested. A related thing is that no-grab does not work on all platforms because it was designed for standard X but nowdays toolkits have their own ideas what is right and what is wrong.

I think the point of my request was originally missed. I will take a screen
capture of the pinentry workflow during authentication and signing tasks -
in my opinion, they should be the same. However, during signing, the window
gets display focus (Windows switches it to the active window), whereas
during authentication it does not (and has to be alt-tabbed/switched to for
pin entry).

aheinecke reopened this task as Open.Sep 19 2018, 9:04 AM

@a_p3rson : Yes. I agree that I think that cepxuo meant something differently then you.

For you it is the input / active window focus which I agree is flaky and does not work fully reliably. So ->Open.

For cepxuo it is the "you cannot input anywhere else" while the pinentry window is open. That is intentionally not done.

I'll update the task description / name a bit to make this more clear.

aheinecke renamed this task from Pinentry-qt does not grab focus when requesting pin for authentication to Pinentry-qt does not always become active foreground window (especially when requesting pin for authentication).Sep 19 2018, 9:06 AM
aheinecke updated the task description. (Show Details)
bb awarded a token.Mar 20 2019, 10:48 AM
bb added a subscriber: bb.

I can also confirm this bug!

Thanks for the confirmation. Although I still don't really know how to fix it :-(

in I think a related scenario we are having the pinentry window not spawn at all, leading to "no pinentry" errors
Win 10 latest patches Mar 2019
Version 3.1.4-gpg4win-3.1.5
We've tried a few hacks including adding the .conf file to C:\Program Files (x86)\GnuPG\bin with
pinentry-program "C:\Program Files (x86)\Gpg4win\bin\pinentry-qt.exe"

C:\WINDOWS\system32>gpg --debug ipc -vK
gpg: reading options from 'C:/Users/nbriggs/AppData/Roaming/gnupg/gpg.conf'
gpg: enabled debug flags: ipc
gpg: using pgp trust model
gpg: DBG: chan_0x00000260 <- OK Pleased to meet you
gpg: DBG: connection to agent established
gpg: DBG: chan_0x00000260 -> RESET
gpg: DBG: chan_0x00000260 <- OK
gpg: DBG: chan_0x00000260 -> GETINFO version
gpg: DBG: chan_0x00000260 <- D 2.2.11
gpg: DBG: chan_0x00000260 <- OK
gpg: DBG: chan_0x00000260 -> OPTION allow-pinentry-notify
gpg: DBG: chan_0x00000260 <- OK
gpg: DBG: chan_0x00000260 -> OPTION agent-awareness=2.1.0
gpg: DBG: chan_0x00000260 <- OK
gpg: DBG: chan_0x00000260 -> HAVEKEY *KEY*
gpg: DBG: chan_0x00000260 <- OK
gpg: DBG: chan_0x00000260 -> KEYINFO *KEY*
gpg: DBG: chan_0x00000260 <- S KEYINFO *KEY* D - - 1 P - - -
gpg: DBG: chan_0x00000260 <- OK
gpg: DBG: chan_0x00000260 -> KEYINFO *KEY*
gpg: DBG: chan_0x00000260 <- S KEYINFO *KEY* D - - - P - - -
gpg: DBG: chan_0x00000260 <- OK

C:/Users/nbriggs/AppData/Roaming/gnupg/pubring.kbx

sec rsa2048 2019-03-25 [SC] [expires: 2021-03-25]


uid [ultimate] Nathan ***
ssb rsa2048 2019-03-25 [E] [expires: 2021-03-25]

gpg: DBG: chan_0x00000260 -> HAVEKEY *KEY*
gpg: DBG: chan_0x00000260 <- ERR 67108881 No secret key <GPG Agent>
gpg: DBG: chan_0x00000260 -> HAVEKEY *KEY*
gpg: DBG: chan_0x00000260 <- ERR 67108881 No secret key <GPG Agent>
gpg: DBG: chan_0x00000260 -> HAVEKEY *KEY*
gpg: DBG: chan_0x00000260 <- ERR 67108881 No secret key <GPG Agent>
gpg: secmem usage: 0/32768 bytes in 0 blocks

Is there anything more I can do, replicated it on 3 different machines

@nbriggs No this is not related if you get "no pinentry" it means pinentry is not started at all. This issue is about pinentry starting but not properly coming to the foreground. I've opened T4430 for your issue.

bb added a comment.Sat, Jul 27, 11:59 AM

Does anyone has an update on this issue?

bb added a comment.Sat, Jul 27, 3:58 PM

Note:
I added:

pinentry-program "C:\Program Files (x86)\Gpg4win\bin\pinentry-gtk-2.exe"

as a workaround to my gpg-agent.conf. This pinentry is able to grab the focus.

a_p3rson added a comment.EditedSun, Jul 28, 12:50 AM

@bb - I've tried this, this doesn't appear to work. It looks like the Gtk2 pinentry doesn't grab focus when doing authentication, either. Interestingly enough, it also doesn't show in the taskbar.

Potentially more helpful output, I've obtained gpg-agent's debug output while performing both signing and authentication operations (command gpg-agent --homedir %APPDATA%/Roaming/gnupg --use-standard-socket --debug-pinentry --debug 1024 --daemon --verbose). Here's what I see from start-to-finish - certain elements in <<Tags>> have been scrubbed to make diffs easier. The TL;DR though is that the calls to pinentry look the same, but there's an INQUIRE PINENTRY_LAUNCHED that occurs when signing but not when authenticating.

Authentication (via plink git@github.com):

gpg-agent[<<PID>>]: reading options from '<<AppDataDir>>/Roaming/gnupg/gpg-agent.conf'
gpg-agent[<<PID>>]: WARNING: "--use-standard-socket" is an obsolete option - it has no effect
gpg-agent[<<PID>>]: enabled debug flags: ipc
gpg-agent[<<PID>>]: listening on socket '<<AppDataDir>>/Roaming/gnupg/S.gpg-agent'
gpg-agent[<<PID>>]: listening on socket '<<AppDataDir>>/Roaming/gnupg/S.gpg-agent.extra'
gpg-agent[<<PID>>]: listening on socket '<<AppDataDir>>/Roaming/gnupg/S.gpg-agent.browser'
gpg-agent[<<PID>>]: listening on socket '<<AppDataDir>>/Roaming/gnupg/S.gpg-agent.ssh'
gpg-agent[<<PID>>]: gpg-agent (GnuPG) 2.2.11 started
gpg-agent[<<PID>>]: putty message loop thread started
gpg-agent[<<PID>>]: DBG: ssh map file 'PageantRequest000030a0'
gpg-agent[<<PID>>]: DBG: ssh map handle 0x000002bc
gpg-agent[<<PID>>]: DBG:           my sid: '<<NTUserSid>>'
gpg-agent[<<PID>>]: DBG: ssh map file sid: '<<NTUserSid>>'
gpg-agent[<<PID>>]: DBG: ssh IPC buffer at 0x001e0000
gpg-agent[<<PID>>]: ssh request handler for request_identities (11) started
gpg-agent[<<PID>>]: no running SCdaemon - starting it
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> <- OK GNU Privacy Guard's Smartcard server ready
gpg-agent[<<PID>>]: DBG: first connection to SCdaemon established
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> -> GETINFO socket_name
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> <- D <<AppDataDir>>/Roaming/gnupg/S.scdaemon
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> <- OK
gpg-agent[<<PID>>]: DBG: additional connections at '<<AppDataDir>>/Roaming/gnupg/S.scdaemon'
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> -> OPTION event-signal=0x0000029c
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> <- OK
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> -> SERIALNO
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> <- S SERIALNO <<CardSerial>>
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> <- OK
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> -> GETINFO card_list
gpg-agent[<<PID>>]: SIGUSR2 received - updating card event counter
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> <- S SERIALNO <<CardSerial>>
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> <- OK
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> -> SERIALNO --demand=<<CardSerial>>
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> <- S SERIALNO <<CardSerial>>
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> <- OK
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> -> GETATTR $AUTHKEYID
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> <- S $AUTHKEYID OPENPGP.3
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> <- OK
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> -> GETATTR SERIALNO
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> <- S SERIALNO <<CardSerial>>
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> <- OK
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> -> READKEY OPENPGP.3
gpg-agent[<<PID>>]: DBG: chan_0x000002e8 -> OK Pleased to meet you
gpg-agent[<<PID>>]: DBG: chan_0x000002e8 <- OPTION ttyname=/dev/tty
gpg-agent[<<PID>>]: DBG: chan_0x000002e8 -> OK
gpg-agent[<<PID>>]: DBG: chan_0x000002e8 <- OPTION allow-pinentry-notify
gpg-agent[<<PID>>]: DBG: chan_0x000002e8 -> OK
gpg-agent[<<PID>>]: DBG: chan_0x000002e8 <- SCD SERIALNO
gpg-agent[<<PID>>]: DBG: chan_000002C4 <- [ 44 20 28 31 30 3a 70 75 62 6c 69 63 2d 6b 65 79 ...(286 byte(s) skipped) ]
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> <- OK
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> -> GETATTR $DISPSERIALNO
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> <- S $DISPSERIALNO 000603813123
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> <- OK
gpg-agent[<<PID>>]: ssh request handler for request_identities (11) ready
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> -> RESTART
gpg-agent[<<PID>>]: DBG: chan_0x00000300 <- OK GNU Privacy Guard's Smartcard server ready
gpg-agent[<<PID>>]: new connection to SCdaemon established
gpg-agent[<<PID>>]: DBG: chan_0x00000300 -> SERIALNO
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> <- OK
gpg-agent[<<PID>>]: DBG: chan_0x00000300 <- S SERIALNO <<CardSerial>>
gpg-agent[<<PID>>]: DBG: chan_0x000002e8 -> S SERIALNO <<CardSerial>>
gpg-agent[<<PID>>]: DBG: chan_0x00000300 <- OK
gpg-agent[<<PID>>]: DBG: chan_0x000002e8 -> OK
gpg-agent[<<PID>>]: DBG: chan_0x000002e8 <- SCD GETATTR APPTYPE
gpg-agent[<<PID>>]: DBG: chan_0x00000300 -> GETATTR APPTYPE
gpg-agent[<<PID>>]: DBG: chan_0x00000300 <- S APPTYPE OPENPGP
gpg-agent[<<PID>>]: DBG: chan_0x000002e8 -> S APPTYPE OPENPGP
gpg-agent[<<PID>>]: DBG: chan_0x00000300 <- OK
gpg-agent[<<PID>>]: DBG: chan_0x000002e8 -> OK
gpg-agent[<<PID>>]: DBG: chan_0x000002e8 <- SCD LEARN --keypairinfo
gpg-agent[<<PID>>]: DBG: chan_0x00000300 -> LEARN --keypairinfo
gpg-agent[<<PID>>]: DBG: chan_0x00000300 <- S EXTCAP gc=1+ki=1+fc=1+pd=0+mcl3=1216+aac=0+sm=2+si=0+dec=0+bt=0+kdf=0
gpg-agent[<<PID>>]: DBG: chan_0x000002e8 -> S EXTCAP gc=1+ki=1+fc=1+pd=0+mcl3=1216+aac=0+sm=2+si=0+dec=0+bt=0+kdf=0
gpg-agent[<<PID>>]: DBG: chan_0x00000300 <- S DISP-NAME <<DisplayName>>
gpg-agent[<<PID>>]: DBG: chan_0x000002e8 -> S DISP-NAME <<DisplayName>>
gpg-agent[<<PID>>]: DBG: chan_0x00000300 <- S DISP-LANG en
gpg-agent[<<PID>>]: DBG: chan_0x000002e8 -> S DISP-LANG en
gpg-agent[<<PID>>]: DBG: chan_0x00000300 <- S DISP-SEX 1
gpg-agent[<<PID>>]: DBG: chan_0x000002e8 -> S DISP-SEX 1
gpg-agent[<<PID>>]: DBG: chan_0x00000300 <- S PUBKEY-URL http://pool.sks-keyservers.net/pks/lookup?op=get&search=0x<<MainKey>>
gpg-agent[<<PID>>]: DBG: chan_0x000002e8 -> S PUBKEY-URL http://pool.sks-keyservers.net/pks/lookup?op=get&search=0x<<MainKey>>
gpg-agent[<<PID>>]: DBG: ssh map file 'PageantRequest000030a0'
gpg-agent[<<PID>>]: DBG: ssh map handle 0x00000094
gpg-agent[<<PID>>]: DBG:           my sid: '<<NTUserSid>>'
gpg-agent[<<PID>>]: DBG: ssh map file sid: '<<NTUserSid>>'
gpg-agent[<<PID>>]: DBG: ssh IPC buffer at 0x001e0000
gpg-agent[<<PID>>]: ssh request handler for sign_request (13) started
gpg-agent[<<PID>>]: new connection to SCdaemon established (reusing)
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> -> SERIALNO --demand=<<CardSerial>>
gpg-agent[<<PID>>]: DBG: chan_0x00000300 <- S KEY-FPR 1 <<Key1Fingerprint>>
gpg-agent[<<PID>>]: DBG: chan_0x000002e8 -> S KEY-FPR 1 <<Key1Fingerprint>>
gpg-agent[<<PID>>]: DBG: chan_0x00000300 <- S KEY-FPR 2 <<Key2Fingerprint>>
gpg-agent[<<PID>>]: DBG: chan_0x000002e8 -> S KEY-FPR 2 <<Key2Fingerprint>>
gpg-agent[<<PID>>]: DBG: chan_0x00000300 <- S KEY-FPR 3 <<Key3Fingerprint>>
gpg-agent[<<PID>>]: DBG: chan_0x000002e8 -> S KEY-FPR 3 <<Key3Fingerprint>>
gpg-agent[<<PID>>]: DBG: chan_0x00000300 <- S KEY-TIME 1 1446882814
gpg-agent[<<PID>>]: DBG: chan_0x000002e8 -> S KEY-TIME 1 1446882814
gpg-agent[<<PID>>]: DBG: chan_0x00000300 <- S KEY-TIME 2 1446873073
gpg-agent[<<PID>>]: DBG: chan_0x000002e8 -> S KEY-TIME 2 1446873073
gpg-agent[<<PID>>]: DBG: chan_0x00000300 <- S KEY-TIME 3 1446882877
gpg-agent[<<PID>>]: DBG: chan_0x000002e8 -> S KEY-TIME 3 1446882877
gpg-agent[<<PID>>]: DBG: chan_0x00000300 <- S CHV-STATUS +0+127+127+127+3+3+3
gpg-agent[<<PID>>]: DBG: chan_0x000002e8 -> S CHV-STATUS +0+127+127+127+3+3+3
gpg-agent[<<PID>>]: DBG: chan_0x00000300 <- S SIG-COUNTER 1615
gpg-agent[<<PID>>]: DBG: chan_0x000002e8 -> S SIG-COUNTER 1615
gpg-agent[<<PID>>]: DBG: chan_0x00000300 <- S KEYPAIRINFO 0410CE266EEC378AA9D0E9D5987BABEA99CFDA3E OPENPGP.1
gpg-agent[<<PID>>]: DBG: chan_0x000002e8 -> S KEYPAIRINFO 0410CE266EEC378AA9D0E9D5987BABEA99CFDA3E OPENPGP.1
gpg-agent[<<PID>>]: DBG: chan_0x00000300 <- S KEYPAIRINFO 1913640DCACA174C5E615D65376F02723D34000F OPENPGP.2
gpg-agent[<<PID>>]: DBG: chan_0x000002e8 -> S KEYPAIRINFO 1913640DCACA174C5E615D65376F02723D34000F OPENPGP.2
gpg-agent[<<PID>>]: DBG: chan_0x00000300 <- S KEYPAIRINFO 64AFC1EC87773BB853A85B587B27155A6CCE8B01 OPENPGP.3
gpg-agent[<<PID>>]: DBG: chan_0x000002e8 -> S KEYPAIRINFO 64AFC1EC87773BB853A85B587B27155A6CCE8B01 OPENPGP.3
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> <- S SERIALNO <<CardSerial>>
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> <- OK
gpg-agent[<<PID>>]: DBG: detected card with S/N <<CardSerial>>
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> -> SETDATA 3021300906052B0E03021A05000414A385FFACC2DBA4CDD0A57F26B654264959C52F8B
gpg-agent[<<PID>>]: DBG: chan_0x00000300 <- OK
gpg-agent[<<PID>>]: DBG: chan_0x000002e8 -> OK
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> <- OK
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> -> PKAUTH OPENPGP.3
gpg-agent[<<PID>>]: DBG: chan_0x000002e8 <- [invalid line]
gpg-agent[<<PID>>]: Assuan processing failed: Incomplete line passed to IPC
gpg-agent[<<PID>>]: DBG: chan_0x00000300 -> BYE
gpg-agent[<<PID>>]: DBG: chan_000002C4 <- [ 49 4e 51 55 49 52 45 20 4e 45 45 44 50 49 4e 20 ...(80 byte(s) skipped) ]
gpg-agent[<<PID>>]: starting a new PIN Entry
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> <- OK Pleased to meet you
gpg-agent[<<PID>>]: DBG: connection to PIN entry established
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> -> OPTION grab
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> <- OK
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> -> OPTION allow-external-password-cache
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> <- OK
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> -> OPTION default-ok=_OK
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> <- OK
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> -> OPTION default-cancel=_Cancel
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> <- OK
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> -> OPTION default-yes=_Yes
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> <- ERR 83886254 Unknown option <Pinentry>
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> -> OPTION default-no=_No
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> <- ERR 83886254 Unknown option <Pinentry>
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> -> OPTION default-prompt=PIN:
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> <- OK
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> -> OPTION default-pwmngr=_Save in password manager
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> <- OK
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> -> OPTION default-cf-visi=Do you really want to make your passphrase visible on the screen?
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> <- OK
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> -> OPTION default-tt-visi=Make passphrase visible
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> <- OK
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> -> OPTION default-tt-hide=Hide passphrase
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> <- OK
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> -> OPTION touch-file=<<AppDataDir>>/Roaming/gnupg/S.gpg-agent
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> <- OK
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> -> GETINFO flavor
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> <- D gtk2
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> <- OK
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> -> GETINFO version
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> <- D 1.1.1-beta5
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> <- OK
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> -> GETINFO ttyinfo
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> <- D - - -
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> <- OK
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> -> GETINFO pid
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> <- D 3300
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> <- OK
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> -> SETKEYINFO --clear
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> <- OK
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> -> SETDESC Please unlock the card%0A%0ANumber: <<CardNum>>%0AHolder: <<FormattedName>>
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> <- OK
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> -> SETPROMPT PIN
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> <- OK
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> -> [[Confidential data not shown]]

Signing (via gpg --sign example.txt):

gpg-agent[<<PID>>]: reading options from '<<AppDataDir>>/Roaming/gnupg/gpg-agent.conf'
gpg-agent[<<PID>>]: WARNING: "--use-standard-socket" is an obsolete option - it has no effect
gpg-agent[<<PID>>]: enabled debug flags: ipc
gpg-agent[<<PID>>]: listening on socket '<<AppDataDir>>/Roaming/gnupg/S.gpg-agent'
gpg-agent[<<PID>>]: listening on socket '<<AppDataDir>>/Roaming/gnupg/S.gpg-agent.extra'
gpg-agent[<<PID>>]: listening on socket '<<AppDataDir>>/Roaming/gnupg/S.gpg-agent.browser'
gpg-agent[<<PID>>]: listening on socket '<<AppDataDir>>/Roaming/gnupg/S.gpg-agent.ssh'
gpg-agent[<<PID>>]: gpg-agent (GnuPG) 2.2.11 started
gpg-agent[<<PID>>]: putty message loop thread started
gpg-agent[<<PID>>]: DBG: chan_0x000002a0 -> OK Pleased to meet you
gpg-agent[<<PID>>]: DBG: chan_0x000002a0 <- RESET
gpg-agent[<<PID>>]: DBG: chan_0x000002a0 -> OK
gpg-agent[<<PID>>]: DBG: chan_0x000002a0 <- GETINFO version
gpg-agent[<<PID>>]: DBG: chan_0x000002a0 -> D 2.2.11
gpg-agent[<<PID>>]: DBG: chan_0x000002a0 -> OK
gpg-agent[<<PID>>]: DBG: chan_0x000002a0 <- OPTION allow-pinentry-notify
gpg-agent[<<PID>>]: DBG: chan_0x000002a0 -> OK
gpg-agent[<<PID>>]: DBG: chan_0x000002a0 <- OPTION agent-awareness=2.1.0
gpg-agent[<<PID>>]: DBG: chan_0x000002a0 -> OK
gpg-agent[<<PID>>]: DBG: chan_0x000002a0 <- SCD SERIALNO openpgp
gpg-agent[<<PID>>]: no running SCdaemon - starting it
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> <- OK GNU Privacy Guard's Smartcard server ready
gpg-agent[<<PID>>]: DBG: first connection to SCdaemon established
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> -> GETINFO socket_name
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> <- D <<AppDataDir>>/Roaming/gnupg/S.scdaemon
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> <- OK
gpg-agent[<<PID>>]: DBG: additional connections at '<<AppDataDir>>/Roaming/gnupg/S.scdaemon'
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> -> OPTION event-signal=0x0000009c
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> <- OK
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> -> SERIALNO openpgp
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> <- S SERIALNO <<CardSerial>>
gpg-agent[<<PID>>]: DBG: chan_0x000002a0 -> S SERIALNO <<CardSerial>>
gpg-agent[<<PID>>]: SIGUSR2 received - updating card event counter
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> <- OK
gpg-agent[<<PID>>]: DBG: chan_0x000002a0 -> OK
gpg-agent[<<PID>>]: DBG: chan_0x000002a0 <- SCD SERIALNO
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> -> SERIALNO
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> <- S SERIALNO <<CardSerial>>
gpg-agent[<<PID>>]: DBG: chan_0x000002a0 -> S SERIALNO <<CardSerial>>
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> <- OK
gpg-agent[<<PID>>]: DBG: chan_0x000002a0 -> OK
gpg-agent[<<PID>>]: DBG: chan_0x000002a0 <- SCD GETATTR KEY-FPR
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> -> GETATTR KEY-FPR
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> <- S KEY-FPR 1 <<Key1Fingerprint>>
gpg-agent[<<PID>>]: DBG: chan_0x000002a0 -> S KEY-FPR 1 <<Key1Fingerprint>>
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> <- S KEY-FPR 2 <<Key2Fingerprint>>
gpg-agent[<<PID>>]: DBG: chan_0x000002a0 -> S KEY-FPR 2 <<Key2Fingerprint>>
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> <- S KEY-FPR 3 <<Key3Fingerprint>>
gpg-agent[<<PID>>]: DBG: chan_0x000002a0 -> S KEY-FPR 3 <<Key3Fingerprint>>
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> <- OK
gpg-agent[<<PID>>]: DBG: chan_0x000002a0 -> OK
gpg-agent[<<PID>>]: DBG: chan_0x000002a0 <- KEYINFO 0410CE266EEC378AA9D0E9D5987BABEA99CFDA3E
gpg-agent[<<PID>>]: DBG: chan_0x000002a0 -> S KEYINFO 0410CE266EEC378AA9D0E9D5987BABEA99CFDA3E T <<CardSerial>> OPENPGP.1 - - - - -
gpg-agent[<<PID>>]: DBG: chan_0x000002a0 -> OK
gpg-agent[<<PID>>]: DBG: chan_0x000002a0 <- RESET
gpg-agent[<<PID>>]: DBG: chan_0x000002a0 -> OK
gpg-agent[<<PID>>]: DBG: chan_0x000002a0 <- SIGKEY 0410CE266EEC378AA9D0E9D5987BABEA99CFDA3E
gpg-agent[<<PID>>]: DBG: chan_0x000002a0 -> OK
gpg-agent[<<PID>>]: DBG: chan_0x000002a0 <- SETKEYDESC Please+enter+the+passphrase+to+unlock+the+OpenPGP+secret+key:%0A%22<<FormattedNameEmail>>%22%0A2048-bit+RSA+key,+ID+<<SigningKey>>,%0Acreated+2015-11-07+(main+key+ID+<<MainKey>>).%0A
gpg-agent[<<PID>>]: DBG: chan_0x000002a0 -> OK
gpg-agent[<<PID>>]: DBG: chan_0x000002a0 <- SETHASH 8 25ECB3218AECFE5CB4FB9806308F5CD99CCAFB29318B971C32BDC69C3DF9DC55
gpg-agent[<<PID>>]: DBG: chan_0x000002a0 -> OK
gpg-agent[<<PID>>]: DBG: chan_0x000002a0 <- PKSIGN
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> -> SERIALNO --demand=<<CardSerial>>
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> <- S SERIALNO <<CardSerial>>
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> <- OK
gpg-agent[<<PID>>]: DBG: detected card with S/N <<CardSerial>>
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> -> SETDATA 3031300D06096086480165030402010500042025ECB3218AECFE5CB4FB9806308F5CD99CCAFB29318B971C32BDC69C3DF9DC55
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> <- OK
gpg-agent[<<PID>>]: DBG: <<SCDaemonChan>> -> PKSIGN --hash=sha256 OPENPGP.1
gpg-agent[<<PID>>]: DBG: chan_0x000002fc -> OK Pleased to meet you
gpg-agent[<<PID>>]: DBG: chan_0x000002fc <- OPTION ttyname=/dev/tty
gpg-agent[<<PID>>]: DBG: chan_0x000002fc -> OK
gpg-agent[<<PID>>]: DBG: chan_0x000002fc <- OPTION allow-pinentry-notify
gpg-agent[<<PID>>]: DBG: chan_0x000002fc -> OK
gpg-agent[<<PID>>]: DBG: chan_0x000002fc <- SCD SERIALNO
gpg-agent[<<PID>>]: DBG: chan_000002C8 <- [ 49 4e 51 55 49 52 45 20 4e 45 45 44 50 49 4e 20 ...(97 byte(s) skipped) ]
gpg-agent[<<PID>>]: starting a new PIN Entry
gpg-agent[<<PID>>]: DBG: chan_0x000002dc <- OK GNU Privacy Guard's Smartcard server ready
gpg-agent[<<PID>>]: new connection to SCdaemon established
gpg-agent[<<PID>>]: DBG: chan_0x000002dc -> SERIALNO
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> <- OK Pleased to meet you
gpg-agent[<<PID>>]: DBG: connection to PIN entry established
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> -> OPTION grab
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> <- OK
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> -> OPTION allow-external-password-cache
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> <- OK
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> -> OPTION default-ok=_OK
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> <- OK
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> -> OPTION default-cancel=_Cancel
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> <- OK
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> -> OPTION default-yes=_Yes
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> <- ERR 83886254 Unknown option <Pinentry>
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> -> OPTION default-no=_No
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> <- ERR 83886254 Unknown option <Pinentry>
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> -> OPTION default-prompt=PIN:
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> <- OK
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> -> OPTION default-pwmngr=_Save in password manager
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> <- OK
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> -> OPTION default-cf-visi=Do you really want to make your passphrase visible on the screen?
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> <- OK
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> -> OPTION default-tt-visi=Make passphrase visible
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> <- OK
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> -> OPTION default-tt-hide=Hide passphrase
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> <- OK
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> -> OPTION touch-file=<<AppDataDir>>/Roaming/gnupg/S.gpg-agent
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> <- OK
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> -> GETINFO flavor
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> <- D gtk2
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> <- OK
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> -> GETINFO version
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> <- D 1.1.1-beta5
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> <- OK
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> -> GETINFO ttyinfo
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> <- D - - -
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> <- OK
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> -> GETINFO pid
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> <- D 2488
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> <- OK
gpg-agent[<<PID>>]: DBG: chan_0x000002a0 -> INQUIRE PINENTRY_LAUNCHED 2488 gtk2 1.1.1-beta5 - - -
gpg-agent[<<PID>>]: DBG: chan_0x000002a0 <- END
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> -> SETKEYINFO --clear
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> <- OK
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> -> SETDESC Please unlock the card%0A%0ANumber: <<CardNum>>%0AHolder: <<FormattedName>>%0ACounter: 1615
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> <- OK
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> -> SETPROMPT PIN
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> <- OK
gpg-agent[<<PID>>]: DBG: <<PINEntryChan>> -> [[Confidential data not shown]]
bb added a comment.Sun, Jul 28, 9:22 PM

False alarm. Turns out pinentry-gtk-2.exe is also not working all the time.

I think the problem is the following:

Windows does not like applications popping up in the foreground, for good reason because that can be annoying. This is difficult for us because pinentry is its own application.

There is a mechanism that allows that. AllowSetForegroundWindow (ProcessID) this must be called from the foreground application and passed to GnuPG, GnuPG then passes that to gpg-agent and gpg-agent passes that to pinentry and pinentry finally calls SetForegroundWindow.

This passing might indeed be triggered by the INQUIRE. I'll have to check the code. Or putty does not set it. But I'm not completely sure, I'll have to test this.