User Details
- User Since
- Mar 27 2017, 4:47 PM (401 w, 1 d)
- Availability
- Available
Jul 23 2015
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.
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
Jul 14 2015
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!
Jul 10 2015
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