Page MenuHome GnuPG

gpgme_set_pinentry_mode GPGME_PINENTRY_MODE_LOOPBACK doesn't work
Closed, ResolvedPublic

Description

At least with gpg2 2.1.4-1 and gpgme 1.5.5-2 the passphrase callback
does not work.
When enabled I get the "secret key unusable" error, and without the
callback (enter passphrase via agent) it works fine.
If I remember correctly you stated that you need gpg2 v2.1 or better
for that to work:
https://lists.gnupg.org/pipermail/gnupg-devel/2015-May/029872.html

Steps:
download http://vps001.vanheusden.com/~folkert/gbug.tgz
unpack it
make
Then:
./gpgme_test E96F346A94A761F898F9DA35D8CD7D21B2A93EF9 test4.txt 1f28d8ae

First parameter is your key-id, second is a text-file containing your
passphrase and the third is the pubkey for which it will sign and
encrypt.
The output looks like:

2015-07-04 18:55:50 (FIXME) GPGME version: 1.5.5
2015-07-04 18:55:50 (FIXME) GPGME protocol: OpenPGP, exe: /usr/bin/gpg2, home-
dir: (null), version: 2.1.4, req version: 1.4.0
2015-07-04 18:55:50 (FIXME) GPGME protocol: CMS, exe: /usr/bin/gpgsm, home-dir:
(null), version: (null), req version: 2.0.4
2015-07-04 18:55:50 (FIXME) GPGME protocol: GPGCONF, exe: /usr/bin/gpgconf,
home-dir: (null), version: 2.1.4, req version: 2.0.4
2015-07-04 18:55:50 (FIXME) GPGME protocol: Assuan, exe:
/home/folkert/.gnupg/S.gpg-agent, home-dir: !GPG_AGENT, version: 1.0,
req version: 1.0
2015-07-04 18:55:50 (FIXME) GPGME protocol: UIServer, exe:
/home/folkert/.gnupg/S.uiserver, home-dir: (null), version: 1.0, req version:
1.0
2015-07-04 18:55:50 (FIXME) GPGME protocol: Spawn, exe: /nonexistent, home-dir:
(null), version: 1.0, req version: 1.0
2015-07-04 18:55:50 (FIXME) my_key_id_in:
E96F346A94A761F898F9DA35D8CD7D21B2A93EF9, found key: D8CD7D21B2A93EF9
2015-07-04 18:55:50 (FIXME) gpgme init success
get_my_keyid: 1
key known: 1

error:

2015-07-04 18:55:50 (FIXME) my_key: D8CD7D21B2A93EF9
encrypt: 0

       error: gpgme_op_encrypt failed: Unusable secret key (117440566)

The "error:" without anythin behind it can be ignored.

Details

Version
1.5.5-2

Event Timeline

flok added projects: Bug Report, gpgme.
flok added a subscriber: flok.

Do you have 'allow-loopback-pinentry' option in your .gnupg/gpg-agent.conf?
It is not enabled by default, since allowing loopback mode gives easier access
to private keys.

I had not. But when I do:

2015-07-10 12:10:07 (gpgme_test) my_key: D8CD7D21B2A93EF9
encrypt: 0
error: gpgme_op_encrypt failed: General error (117440513)

folkert@travelmate:~/Projects/PGF/trunk$ cat ~/.gnupg/gpg-agent.conf
allow-loopback-pinentry

Did an strace (with fork-follow) of my code and saw the following:

The first is a sign + encrypt:

[pid 19904] execve("/usr/bin/gpg2", ["gpg2", "--enable-special-filenames", "--
batch", "--no-sk-comments", "--lc-messages", "C", "--lc-ctype", "C", "--status-
fd", "4", "--no-tty", "--charset", "utf8", "--enable-progress-filter", "--
display", ":0.0", "--encrypt", "--sign", "--always-trust", "-r",
"E96F346A94A761F898F9DA35D8CD7D21B2A93EF9", "-u", "D8CD7D21B2A93EF9", "--
output", "-", "--", "-&7"], [/* 30 vars */]) = 0

The second is a decrypt:

[pid 19907] execve("/usr/bin/gpg2", ["gpg2", "--enable-special-filenames", "--
pinentry-mode=loopback", "--no-sk-comments", "--lc-messages", "C", "--lc-ctype",
"C", "--status-fd", "4", "--no-tty", "--charset", "utf8", "--enable-progress-
filter", "--display", ":0.0", "--command-fd", "5", "--decrypt", "--output", "-",
"--", "-&9"], [/* 30 vars */]) = 0

Now the decrypt does a --pinentry-mode=loopback while the sign, which also
requires password interaction, does not!

A brief check shows that the pinentry mode is passed to the egine for decrypt
and sign. Please double check your code that you set the pinentry mode for the
conext before signing. You should also set GPGME_DEBUG=4:/foo/bar/logfile for a
log.

Werner Koch <wk@gnupg.org> added the comment:

A brief check shows that the pinentry mode is passed to the egine for decrypt
and sign. Please double check your code that you set the pinentry mode for

the

conext before signing. You should also set GPGME_DEBUG=4:/foo/bar/logfile for

a

log.

I found that on some systems it works and on some it doesn't.

working:
ii gnupg 1.4.18-7
ii gnupg-agent 2.1.4-1
ii gnupg2 2.1.4-1
ii libgpgme++2 4:4.14.2-2+b1
ii libgpgme11:amd64 1.5.5-2
ii libgpgme11-dev 1.5.5-2
ii python-gnupginterface 0.3.2-9.1

failing:
ii gnupg 1.4.18-4
ii gnupg-agent 2.1.6-1
ii gnupg2 2.1.6-1
ii libgpgme++2 4:4.14.2-2+b1
ii libgpgme11:amd64 1.5.5-3
ii libgpgme11-dev 1.5.5-3

Tested it on 3 different debian systems.

When doing an strace, I see the following:

write(1, "85:1060269507::::::e::::::\nfpr::"..., 4096) = -1 EPIPE (Broken pipe)

  • SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=25365, si_uid=1000} ---

write(1, "85:1060269507::::::e::::::\nfpr::"..., 4096) = -1 EPIPE (Broken pipe)

  • SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=25365, si_uid=1000} ---

write(1, "85:1060269507::::::e::::::\nfpr::"..., 4096) = -1 EPIPE (Broken pipe)

  • SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=25365, si_uid=1000} ---

write(1, "85:1060269507::::::e::::::\nfpr::"..., 4096) = -1 EPIPE (Broken pipe)

  • SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=25365, si_uid=1000} ---

write(1, "85:1060269507::::::e::::::\nfpr::"..., 4096) = -1 EPIPE (Broken pipe)

  • SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=25365, si_uid=1000} ---

write(1, "85:1060269507::::::e::::::\nfpr::"..., 4096) = -1 EPIPE (Broken pipe)

  • SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=25365, si_uid=1000} ---

...ad infinitum

So it looks like gpg2 tries to send more data to gpgme but maybe it
closed the file descriptor? Maybe some timeout?

The trace also speaks about an error but I don't know what the number
means:

GPGME 2015-07-22 23:18:39 <0x66f2> gpgme_new: enter: r_ctx=0x7ffce1a86a18
GPGME 2015-07-22 23:18:39 <0x66f2> gpgme_new: leave: ctx=0x6a2b40
GPGME 2015-07-22 23:18:39 <0x66f2> gpgme_set_passphrase_cb: call: ctx=0x6a2b40,
passphrase_cb=(nil)/(nil)
GPGME 2015-07-22 23:18:39 <0x66f2> gpgme_set_pinentry_mode: call: ctx=0x6a2b40,
pinentry_mode=4
GPGME 2015-07-22 23:18:39 <0x66f2> gpgme_set_passphrase_cb: call: ctx=0x6a2b40,
passphrase_cb=0x4130c0/0x6a6488
GPGME 2015-07-22 23:18:39 <0x66f2> gpgme_new: enter: r_ctx=0x7ffce1a869b8
GPGME 2015-07-22 23:18:39 <0x66f2> gpgme_new: leave: ctx=0x694a30
GPGME 2015-07-22 23:18:39 <0x66f2> gpgme_op_keylist_start: enter: ctx=0x694a30,
pattern=9101D24C869F57E712BCB6BC435F59B679A28EB6, secret_only=0
GPGME 2015-07-22 23:18:39 <0x66f2> _gpgme_add_io_cb: call: ctx=0x694a30, fd
5, dir=1 -> tag=0x697670
GPGME 2015-07-22 23:18:39 <0x66f2> _gpgme_add_io_cb: call: ctx=0x694a30, fd
7, dir=1 -> tag=0x6977d0
GPGME 2015-07-22 23:18:39 <0x66f2> gpgme:gpg_io_event: call: gpg=0x6a3bd0,
event 0x7fb66f730eb0, type 0, type_data (nil)
GPGME 2015-07-22 23:18:39 <0x66f2> gpgme_op_keylist_start: leave
GPGME 2015-07-22 23:18:39 <0x66f2> gpgme_op_keylist_next: enter: ctx=0x694a30
GPGME 2015-07-22 23:18:39 <0x66f2> _gpgme_run_io_cb: call: item=0x697800,
need to check
GPGME 2015-07-22 23:18:39 <0x66f2> _gpgme_run_io_cb: call: item=0x697800,
handler (0x6a3bd0, 7)
GPGME 2015-07-22 23:18:39 <0x66f2> gpgme:keylist_colon_handler: call:
ctx=0x694a30, key = (nil), line = tru::0:1437598451:1438634760:3:1:5
GPGME 2015-07-22 23:18:39 <0x66f2> gpgme:keylist_colon_handler: call:
ctx=0x694a30, key = (nil), line = pub:u:4096:1:435F59B679A28EB6:1437562181:::-
:::scESC::::::
GPGME 2015-07-22 23:18:39 <0x66f2> gpgme:keylist_colon_handler: call:
ctx=0x694a30, key = 0x697830, line =
fpr:::::::::9101D24C869F57E712BCB6BC435F59B679A28EB6:
GPGME 2015-07-22 23:18:39 <0x66f2> gpgme:keylist_colon_handler: call:
ctx=0x694a30, key = 0x697830, line =
uid:u::::1437562181::67B02486BE612BD1F799DD1EF250DA9FDB9C601C::pgf test key (pgf
test key) <test@vanheusden.com>:
GPGME 2015-07-22 23:18:39 <0x66f2> gpgme:keylist_colon_handler: call:
ctx=0x694a30, key = 0x697830, line =
sub:u:4096:1:3B7DB05915752DE2:1437562181::::::e::::::
GPGME 2015-07-22 23:18:39 <0x66f2> gpgme:keylist_colon_handler: call:
ctx=0x694a30, key = 0x697830, line =
fpr:::::::::1D4A144B830EBD875B3A17D73B7DB05915752DE2:
GPGME 2015-07-22 23:18:39 <0x66f2> gpgme:keylist_colon_handler: call:
ctx=0x694a30, key = 0x697830, line =
pub:u:4096:1:435F59B679A28EB6:1437562181:::-:::scESC::::::
GPGME 2015-07-22 23:18:39 <0x66f2> gpgme:gpg_io_event: call: gpg=0x6a3bd0,
event 0x7fb66f730eb0, type 2, type_data 0x697830
GPGME 2015-07-22 23:18:39 <0x66f2> gpgme:keylist_colon_handler: call:
ctx=0x694a30, key = 0x697a70, line =
fpr:::::::::9101D24C869F57E712BCB6BC435F59B679A28EB6:
GPGME 2015-07-22 23:18:39 <0x66f2> gpgme:keylist_colon_handler: call:
ctx=0x694a30, key = 0x697a70, line =
uid:u::::1437562181::67B02486BE612BD1F799DD1EF250DA9FDB9C601C::pgf test key (pgf
test key) <test@vanheusden.com>:
GPGME 2015-07-22 23:18:39 <0x66f2> gpgme:keylist_colon_handler: call:
ctx=0x694a30, key = 0x697a70, line =
sub:u:4096:1:3B7DB05915752DE2:1437562181::::::e::::::
GPGME 2015-07-22 23:18:39 <0x66f2> gpgme:keylist_colon_handler: call:
ctx=0x694a30, key = 0x697a70, line =
fpr:::::::::1D4A144B830EBD875B3A17D73B7DB05915752DE2:
GPGME 2015-07-22 23:18:39 <0x66f2> gpgme_op_keylist_next: leave: key=0x697830
(9101D24C869F57E712BCB6BC435F59B679A28EB6)
GPGME 2015-07-22 23:18:39 <0x66f2> gpgme_release: call: ctx=0x694a30
GPGME 2015-07-22 23:18:39 <0x66f2> _gpgme_remove_io_cb: call: data=0x697670,
setting fd 0x5 (item=0x6976a0) done
GPGME 2015-07-22 23:18:39 <0x66f2> _gpgme_remove_io_cb: call: data=0x6977d0,
setting fd 0x7 (item=0x697800) done
GPGME 2015-07-22 23:18:39 <0x66f2> gpgme_signers_clear: call: ctx=0x6a2b40
GPGME 2015-07-22 23:18:39 <0x66f2> gpgme_signers_add: enter: ctx=0x6a2b40,
key=0x694bc0 (387FB9C2DE84B200436962A0207A035AD316FA65)
GPGME 2015-07-22 23:18:39 <0x66f2> gpgme_signers_add: leave
GPGME 2015-07-22 23:18:39 <0x66f2> gpgme_op_encrypt_sign: enter: ctx=0x6a2b40,
flags=0x1, plain=0x695240, cipher=0x696290
GPGME 2015-07-22 23:18:39 <0x66f2> gpgme_op_encrypt_sign: check: ctx=0x6a2b40,
recipient[0] = 0x697830 (9101D24C869F57E712BCB6BC435F59B679A28EB6)
GPGME 2015-07-22 23:18:39 <0x66f2> gpgme_sig_notation_get: call:
ctx=0x6a2b40, ctx->sig_notations=(nil)
GPGME 2015-07-22 23:18:39 <0x66f2> _gpgme_add_io_cb: call: ctx=0x6a2b40, fd
5, dir=1 -> tag=0x693e10
GPGME 2015-07-22 23:18:39 <0x66f2> _gpgme_add_io_cb: call: ctx=0x6a2b40, fd
9, dir=1 -> tag=0x693f70
GPGME 2015-07-22 23:18:39 <0x66f2> _gpgme_add_io_cb: call: ctx=0x6a2b40, fd
12, dir=0 -> tag=0x693fd0
GPGME 2015-07-22 23:18:39 <0x66f2> gpgme:gpg_io_event: call: gpg=0x6a3bd0,
event 0x7fb66f730eb0, type 0, type_data (nil)
GPGME 2015-07-22 23:18:39 <0x66f2> _gpgme_run_io_cb: call: item=0x694000,
need to check
GPGME 2015-07-22 23:18:39 <0x66f2> _gpgme_run_io_cb: call: item=0x694000,
handler (0x695240, 12)
GPGME 2015-07-22 23:18:39 <0x66f2> _gpgme_data_outbound_handler: enter:
dh=0x695240, fd=0xc
GPGME 2015-07-22 23:18:39 <0x66f2> _gpgme_data_outbound_handler: leave
GPGME 2015-07-22 23:18:39 <0x66f2> _gpgme_run_io_cb: call: item=0x694000,
need to check
GPGME 2015-07-22 23:18:39 <0x66f2> _gpgme_run_io_cb: call: item=0x694000,
handler (0x695240, 12)
GPGME 2015-07-22 23:18:39 <0x66f2> _gpgme_data_outbound_handler: enter:
dh=0x695240, fd=0xc
GPGME 2015-07-22 23:18:39 <0x66f2> _gpgme_remove_io_cb: call:
data=0x693fd0, setting fd 0xc (item=0x694000) done
GPGME 2015-07-22 23:18:39 <0x66f2> _gpgme_data_outbound_handler: leave
GPGME 2015-07-22 23:18:39 <0x66f2> _gpgme_run_io_cb: call: item=0x693e40,
need to check
GPGME 2015-07-22 23:18:39 <0x66f2> _gpgme_run_io_cb: call: item=0x693e40,
handler (0x6a3bd0, 5)
GPGME 2015-07-22 23:18:39 <0x66f2> _gpgme_run_io_cb: call: item=0x693e40,
need to check
GPGME 2015-07-22 23:18:39 <0x66f2> _gpgme_run_io_cb: call: item=0x693e40,
handler (0x6a3bd0, 5)
GPGME 2015-07-22 23:18:39 <0x66f2> _gpgme_run_io_cb: call: item=0x693fa0,
need to check
GPGME 2015-07-22 23:18:39 <0x66f2> _gpgme_run_io_cb: call: item=0x693fa0,
handler (0x696290, 9)
GPGME 2015-07-22 23:18:39 <0x66f2> _gpgme_data_inbound_handler: enter:
dh=0x696290, fd=0x9
GPGME 2015-07-22 23:18:39 <0x66f2> _gpgme_data_inbound_handler: leave
GPGME 2015-07-22 23:18:39 <0x66f2> _gpgme_run_io_cb: call: item=0x693e40,
need to check
GPGME 2015-07-22 23:18:39 <0x66f2> _gpgme_run_io_cb: call: item=0x693e40,
handler (0x6a3bd0, 5)
GPGME 2015-07-22 23:18:39 <0x66f2> _gpgme_run_io_cb: call: item=0x693e40,
need to check
GPGME 2015-07-22 23:18:39 <0x66f2> _gpgme_run_io_cb: call: item=0x693e40,
handler (0x6a3bd0, 5)
GPGME 2015-07-22 23:18:39 <0x66f2> _gpgme_run_io_cb: call: item=0x693fa0,
need to check
GPGME 2015-07-22 23:18:39 <0x66f2> _gpgme_run_io_cb: call: item=0x693fa0,
handler (0x696290, 9)
GPGME 2015-07-22 23:18:39 <0x66f2> _gpgme_data_inbound_handler: enter:
dh=0x696290, fd=0x9
GPGME 2015-07-22 23:18:39 <0x66f2> _gpgme_data_inbound_handler: leave
GPGME 2015-07-22 23:18:39 <0x66f2> _gpgme_run_io_cb: call: item=0x693e40,
need to check
GPGME 2015-07-22 23:18:39 <0x66f2> _gpgme_run_io_cb: call: item=0x693e40,
handler (0x6a3bd0, 5)
GPGME 2015-07-22 23:18:39 <0x66f2> _gpgme_cancel_with_err: enter:
ctx=0x6a2b40, ctx_err=117440513, op_err=0
GPGME 2015-07-22 23:18:39 <0x66f2> _gpgme_remove_io_cb: call:
data=0x693e10, setting fd 0x5 (item=0x693e40) done
GPGME 2015-07-22 23:18:39 <0x66f2> _gpgme_remove_io_cb: call:
data=0x693f70, setting fd 0x9 (item=0x693fa0) done
GPGME 2015-07-22 23:18:39 <0x66f2> gpgme:gpg_io_event: call: gpg=0x6a3bd0,
event 0x7fb66f730eb0, type 1, type_data 0x7ffce1a86910
GPGME 2015-07-22 23:18:39 <0x66f2> _gpgme_cancel_with_err: leave
GPGME 2015-07-22 23:18:39 <0x66f2> gpgme_op_encrypt_sign:178: error: General
error <GPGME>
GPGME 2015-07-22 23:18:39 <0x66f2> gpgme_release: call: ctx=0x6a2b40

Ok I found why it did not work on a system:

[pid 6507] write(7, "OPTION pinentry-mode=loopback", 29) = 29
[pid 6507] write(7, "\n", 1) = 1
[pid 6507] read(7, "ERR 67108924 Not supported <GPG Agent>\n", 1002) = 39
[pid 6507] brk(0x7f87645c0000) = 0x7f87645c0000
[pid 6507] write(2, "gpg: setting pinentry mode 'loopback' failed: Not
supported", 59) = 59

This is caused by a gpg-agent running with DISPLAY=... set.

Imho there's room for improvement regarding error messages/trace messages:
'general error' is unusable.
Also all those hex-codes in the tracing with no explanations and pointers to
objects that tell you nothing is not helping.

Debug message are for debugging and thus you need access to the source.
I'll see what I can do regarding better error messages for signing.

With the current gpgme and gnupg master things should be a bit better.

werner removed a project: Restricted Project.