GnuPG 2.1.15 - delete-secret-keys seems not to accept loopback pinentry

[Vinay Sajip]

I've made some progress with getting GnuPG 2.1.15 to accept passphrases on fd 0 - it seems to work now for e.g. decryption operations. However, deleting secret keys still seems to fail. Environment is Ubuntu 16.04.1 (64-bit), GnuPG 2.1.15 built from source.

$ cat keys/gpg-agent.conf 

allow-loopback-pinentry
log-file socket:///tmp/S.my-gnupg-log
verbose
debug ipc

Output from watchgnupg --time-only --force /tmp/S.my-gnupg-log:
  4 - 17:46:12 gpg-agent[14900]: handler 0x7ff2ff4f6700 for fd 5 started
  4 - 17:46:12 gpg-agent[14900]: DBG: chan_5 -> OK Pleased to meet you, process 14926
  4 - 17:46:12 gpg-agent[14900]: DBG: chan_5 <- RESET
  4 - 17:46:12 gpg-agent[14900]: DBG: chan_5 -> OK
  4 - 17:46:12 gpg-agent[14900]: DBG: chan_5 <- OPTION ttytype=xterm-256color
  4 - 17:46:12 gpg-agent[14900]: DBG: chan_5 -> OK
  4 - 17:46:12 gpg-agent[14900]: DBG: chan_5 <- OPTION display=:0
  4 - 17:46:12 gpg-agent[14900]: DBG: chan_5 -> OK
  4 - 17:46:12 gpg-agent[14900]: DBG: chan_5 <- OPTION xauthority=/home/vinay/.Xauthority
  4 - 17:46:12 gpg-agent[14900]: DBG: chan_5 -> OK
  4 - 17:46:12 gpg-agent[14900]: DBG: chan_5 <- OPTION putenv=XMODIFIERS=@im=ibus
  4 - 17:46:12 gpg-agent[14900]: DBG: chan_5 -> OK
  4 - 17:46:12 gpg-agent[14900]: DBG: chan_5 <- OPTION putenv=GTK_IM_MODULE=ibus
  4 - 17:46:12 gpg-agent[14900]: DBG: chan_5 -> OK
  4 - 17:46:12 gpg-agent[14900]: DBG: chan_5 <- OPTION putenv=DBUS_SESSION_BUS_ADDRESS=unix:abstract=/tmp/dbus-DYgUN0UGwd
  4 - 17:46:12 gpg-agent[14900]: DBG: chan_5 -> OK
  4 - 17:46:12 gpg-agent[14900]: DBG: chan_5 <- OPTION putenv=QT_IM_MODULE=ibus
  4 - 17:46:12 gpg-agent[14900]: DBG: chan_5 -> OK
  4 - 17:46:12 gpg-agent[14900]: DBG: chan_5 <- GETINFO version
  4 - 17:46:12 gpg-agent[14900]: DBG: chan_5 -> D 2.1.15
  4 - 17:46:12 gpg-agent[14900]: DBG: chan_5 -> OK
  4 - 17:46:12 gpg-agent[14900]: DBG: chan_5 <- OPTION allow-pinentry-notify
  4 - 17:46:12 gpg-agent[14900]: DBG: chan_5 -> OK
  4 - 17:46:12 gpg-agent[14900]: DBG: chan_5 <- OPTION agent-awareness=2.1.0
  4 - 17:46:12 gpg-agent[14900]: DBG: chan_5 -> OK
  4 - 17:46:12 gpg-agent[14900]: DBG: chan_5 <- OPTION pinentry-mode=loopback
  4 - 17:46:12 gpg-agent[14900]: DBG: chan_5 -> OK
  4 - 17:46:12 gpg-agent[14900]: DBG: chan_5 <- AGENT_ID
  4 - 17:46:12 gpg-agent[14900]: DBG: chan_5 -> ERR 67109139 Unknown IPC command <GPG Agent>
  4 - 17:46:12 gpg-agent[14900]: DBG: chan_5 <- HAVEKEY E957503A4483EFA081EBF906B52DBB4B621814FF
  4 - 17:46:12 gpg-agent[14900]: DBG: chan_5 -> OK
  4 - 17:46:12 gpg-agent[14900]: DBG: chan_5 <- HAVEKEY E957503A4483EFA081EBF906B52DBB4B621814FF
  4 - 17:46:12 gpg-agent[14900]: DBG: chan_5 -> OK
  4 - 17:46:12 gpg-agent[14900]: DBG: chan_5 <- SETKEYDESC Do+you+really+want+to+permanently+delete+the+OpenPGP+secret+key:%0A%22Autogenerated+Key+<user1 at test>%22%0A2048-bit+RSA+key,+ID+8F03D92FB77E3265,%0Acreated+2016-11-15.%0A?
  4 - 17:46:12 gpg-agent[14900]: DBG: chan_5 -> OK
  4 - 17:46:12 gpg-agent[14900]: DBG: chan_5 <- DELETE_KEY E957503A4483EFA081EBF906B52DBB4B621814FF
  4 - 17:46:12 gpg-agent[14900]: command 'DELETE_KEY' failed: No PINentry
  4 - 17:46:12 gpg-agent[14900]: DBG: chan_5 -> ERR 67108949 No PINentry <GPG Agent>
  4 - 17:46:12 gpg-agent[14900]: DBG: chan_5 <- [eof]
  4 - 17:46:12 gpg-agent[14900]: handler 0x7ff2ff4f6700 for fd 5 terminated

My test run log file:
14926: /home/vinay/tmp/bin/gpg2 --pinentry-mode loopback --status-fd 2 --no-tty --debug ipc --homedir /home/vinay/projects/python-gnupg/keys --batch --passphrase-fd 0 --debug-quick-random --batch --delete-secret-key B1743E3C7D6DC65F44720E548F03D92FB77E3265
Wrote passphrase
gpg: Note: no default option file '/home/vinay/projects/python-gnupg/keys/gpg.conf'
gpg: enabled debug flags: ipc
gpg: DBG: chan_6 <- OK Pleased to meet you, process 14926
gpg: DBG: connection to agent established
gpg: DBG: chan_6 -> RESET
gpg: DBG: chan_6 <- OK
gpg: DBG: chan_6 -> OPTION ttytype=xterm-256color
gpg: DBG: chan_6 <- OK
gpg: DBG: chan_6 -> OPTION display=:0
gpg: DBG: chan_6 <- OK
gpg: DBG: chan_6 -> OPTION xauthority=/home/vinay/.Xauthority
gpg: DBG: chan_6 <- OK
gpg: DBG: chan_6 -> OPTION putenv=XMODIFIERS=@im=ibus
gpg: DBG: chan_6 <- OK
gpg: DBG: chan_6 -> OPTION putenv=GTK_IM_MODULE=ibus
gpg: DBG: chan_6 <- OK
gpg: DBG: chan_6 -> OPTION putenv=DBUS_SESSION_BUS_ADDRESS=unix:abstract=/tmp/dbus-DYgUN0UGwd
gpg: DBG: chan_6 <- OK
gpg: DBG: chan_6 -> OPTION putenv=QT_IM_MODULE=ibus
gpg: DBG: chan_6 <- OK
gpg: DBG: chan_6 -> GETINFO version
gpg: DBG: chan_6 <- D 2.1.15
gpg: DBG: chan_6 <- OK
gpg: DBG: chan_6 -> OPTION allow-pinentry-notify
gpg: DBG: chan_6 <- OK
gpg: DBG: chan_6 -> OPTION agent-awareness=2.1.0
gpg: DBG: chan_6 <- OK
gpg: DBG: chan_6 -> OPTION pinentry-mode=loopback
gpg: DBG: chan_6 <- OK
gpg: DBG: chan_6 -> AGENT_ID
gpg: DBG: chan_6 <- ERR 67109139 Unknown IPC command <GPG Agent>
gpg: DBG: chan_6 -> HAVEKEY E957503A4483EFA081EBF906B52DBB4B621814FF
gpg: DBG: chan_6 <- OK
gpg: DBG: chan_6 -> HAVEKEY E957503A4483EFA081EBF906B52DBB4B621814FF
gpg: DBG: chan_6 <- OK
[GNUPG:] KEY_CONSIDERED B1743E3C7D6DC65F44720E548F03D92FB77E3265 0
gpg: DBG: chan_6 -> SETKEYDESC Do+you+really+want+to+permanently+delete+the+OpenPGP+secret+key:%0A%22Autogenerated+Key+<user1 at test>%22%0A2048-bit+RSA+key,+ID+8F03D92FB77E3265,%0Acreated+2016-11-15.%0A?
gpg: DBG: chan_6 <- OK
gpg: DBG: chan_6 -> DELETE_KEY E957503A4483EFA081EBF906B52DBB4B621814FF
gpg: DBG: chan_6 <- ERR 67108949 No PINentry <GPG Agent>
gpg: deleting secret key failed: No PINentry
gpg: B1743E3C7D6DC65F44720E548F03D92FB77E3265: delete key failed: No PINentry
gpg: secmem usage: 224/32768 bytes in 1 blocks

The first line of my test run log indicates the PID and command line of the gpg process. This ties up with the watchgnupg program output. The "OPTION pinentry-mode=loopback" seems to have been accepted. I don't understand why the AGENT_ID causes the "ERR 67109139 Unknown IPC command <GPG Agent>" or whether it is relevant to the later failure. Why does DELETE_KEY fail with "No PINentry", and how can I avoid this? As far as I can tell, the passphrase was written successfully on fd 0 (the 2nd line in my test run log, "Wrote passphrase").
Can anyone shed any light on this?
Regards,
Vinay Sajip
-------------- next part --------------
An HTML attachment was scrubbed...
URL: </pipermail/attachments/20161115/c9afb130/attachment-0001.html>